Skip to content

Commit 820ef2c

Browse files
committed
libunwind backtracing performance improved
1 parent 3d0d7d7 commit 820ef2c

File tree

8 files changed

+137
-19
lines changed

8 files changed

+137
-19
lines changed

ChangeLog

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,7 @@
11

2+
0.4.0b2 Mon Aug 3 22:14:21 CEST 2015
3+
- libunwind backtracing performance optimized
4+
25
0.4.0b Sun Aug 2 22:20:42 CEST 2015
36
- use libunwind for backtrace if available
47
- scripts modified to support decoding of libuwind based backtrace

README

Lines changed: 11 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -161,11 +161,19 @@ Web : http://devel.dob.sk/log-malloc2
161161
- PERFORMANCE TIPS -
162162
--------------------
163163

164+
* Ensure that libunwind is enabled
165+
166+
Libunwind generates backtrace approx. 2x faster than GNU backtrace().
167+
With libunwind there is only single write() used for logging (compared to at
168+
least 2 calls when using backtrace()). Futhermore, there is no protective mutex
169+
locking needed, what should reduce waits in multi-threaded programs.
170+
164171
* Log to tmpfs, or other FS that handles write operation effectively
165172

166-
If traced application intensively allocates memory, consider logging to tmpf
167-
because writting to trace fd is the slowest operation, that migbt be in addition
168-
protected by a mutex, thus serializing multithreaded memory allocations.
173+
If traced application intensively allocates memory, consider logging to tmpfs
174+
because writting to trace fd is the slowest operation, that might be in addition
175+
protected by a mutex (if GNU backtrace is used), thus serializing multithreaded
176+
memory allocations.
169177

170178

171179
---------------------------------

config.h.in

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -66,6 +66,9 @@
6666
/* Use libunwind for backtrace */
6767
#undef HAVE_UNWIND
6868

69+
/* Generate detailed libunwind backtrace */
70+
#undef HAVE_UNWIND_DETAIL
71+
6972
/* Define to the sub-directory where libtool stores uninstalled libraries. */
7073
#undef LT_OBJDIR
7174

configure

Lines changed: 29 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -766,6 +766,7 @@ with_gnu_ld
766766
with_sysroot
767767
enable_libtool_lock
768768
with_libunwind
769+
with_libunwind_detail
769770
enable_optimize
770771
enable_call_count
771772
enable_usable_size
@@ -1424,7 +1425,8 @@ Optional Packages:
14241425
--with-gnu-ld assume the C compiler uses GNU ld [default=no]
14251426
--with-sysroot[=DIR] Search for dependent libraries within DIR (or the
14261427
compiler's sysroot if not specified).
1427-
--with-libunwind use libunwind for backtrace
1428+
--without-libunwind do not use libunwind for backtrace
1429+
--with-libunwind-detail more details in libunwind backtrace
14281430

14291431
Some influential environment variables:
14301432
CXX C++ compiler command
@@ -15922,9 +15924,20 @@ no_libunwind=no
1592215924

1592315925
# Check whether --with-libunwind was given.
1592415926
if test "${with_libunwind+set}" = set; then :
15925-
withval=$with_libunwind; no_libunwind=no
15927+
withval=$with_libunwind; no_libunwind=yes
1592615928
else
15927-
no_libunwind=yes
15929+
no_libunwind=no
15930+
15931+
fi
15932+
15933+
15934+
libunwind_detail=no
15935+
15936+
# Check whether --with-libunwind-detail was given.
15937+
if test "${with_libunwind_detail+set}" = set; then :
15938+
withval=$with_libunwind_detail; libunwind_detail=yes
15939+
else
15940+
libunwind_detail=no
1592815941

1592915942
fi
1593015943

@@ -15939,6 +15952,12 @@ else
1593915952
fi
1594015953

1594115954

15955+
15956+
if test "x$libunwind_detail" = "xyes"; then
15957+
15958+
$as_echo "#define HAVE_UNWIND_DETAIL 1" >>confdefs.h
15959+
15960+
fi
1594215961
fi
1594315962

1594415963
no_optimize=no
@@ -18575,3 +18594,10 @@ if test -n "$ac_unrecognized_opts" && test "$enable_option_checking" != no; then
1857518594
$as_echo "$as_me: WARNING: unrecognized options: $ac_unrecognized_opts" >&2;}
1857618595
fi
1857718596

18597+
18598+
# config results
18599+
echo
18600+
echo "HAVE_UNWIND $libunwind"
18601+
echo "HAVE_UNWIND_DETAIL $libunwind_detail"
18602+
echo
18603+

configure.ac

Lines changed: 19 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -37,13 +37,23 @@ Can't find the pthread library (libpthread.so) !])])
3737

3838
no_libunwind=no
3939
AC_ARG_WITH([libunwind],
40-
AS_HELP_STRING([--with-libunwind], [use libunwind for backtrace]),
41-
[no_libunwind=no], [no_libunwind=yes]
40+
AS_HELP_STRING([--without-libunwind], [do not use libunwind for backtrace]),
41+
[no_libunwind=yes], [no_libunwind=no]
42+
)
43+
44+
libunwind_detail=no
45+
AC_ARG_WITH([libunwind-detail],
46+
AS_HELP_STRING([--with-libunwind-detail], [more details in libunwind backtrace]),
47+
[libunwind_detail=yes], [libunwind_detail=no]
4248
)
4349

4450
libunwind=no
4551
if test "x$no_libunwind" != "xyes"; then
4652
AC_CHECK_HEADER([libunwind.h], [libunwind=yes], [libunwind=no])
53+
54+
if test "x$libunwind_detail" = "xyes"; then
55+
AC_DEFINE(HAVE_UNWIND_DETAIL, 1, [Generate detailed libunwind backtrace])
56+
fi
4757
fi
4858

4959
no_optimize=no
@@ -102,3 +112,10 @@ AC_CONFIG_FILES([Makefile])
102112
AC_CONFIG_FILES([log-malloc2.pc])
103113
AC_CONFIG_FILES([scripts/log-malloc.pm])
104114
AC_OUTPUT
115+
116+
# config results
117+
echo
118+
echo "HAVE_UNWIND $libunwind"
119+
echo "HAVE_UNWIND_DETAIL $libunwind_detail"
120+
echo
121+

scripts/backtrace2line.pl

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -243,13 +243,13 @@ ($$$@)
243243

244244
next if($sym eq "[0x0]");
245245
verbose(1, "SYM_PARSE_FAILED: $sym\n"), next
246-
if(!($sym =~ /^(.*?)\((.*?)\)?\[(.*?)\]$/o));
247-
my ($exe, $offset, $addr) = ($1, $2, $3);
246+
if(!($sym =~ /^\s*((.*?)\((.*?)\))?\[(.*?)\]\s*$/o));
247+
my ($exe, $offset, $addr) = ($2, $3, $4);
248248

249249
my $libOffset = 0;
250250
my $addrNum = addr2num($addr);
251251

252-
if($exe ne '*')
252+
if($exe && $exe ne '*')
253253
{
254254
my $exeBN = basename($exe);
255255

src/log-malloc2.c

Lines changed: 66 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -56,8 +56,12 @@
5656
#include <signal.h>
5757
#include <errno.h>
5858
#include <malloc.h>
59+
#include <time.h>
5960

6061
#ifdef HAVE_UNWIND
62+
/* speedup unwinding */
63+
#define UNW_LOCAL_ONLY 1
64+
6165
#include <libunwind.h>
6266
#endif
6367

@@ -68,8 +72,12 @@
6872

6973
/* config */
7074
#ifdef HAVE_UNWIND
75+
#ifdef HAVE_UNWIND_DETAIL
7176
#define LOG_BUFSIZE (128 + (256 * LOG_MALLOC_BACKTRACE_COUNT))
7277
#else
78+
#define LOG_BUFSIZE (128 + (32 * LOG_MALLOC_BACKTRACE_COUNT))
79+
#endif
80+
#else
7381
#define LOG_BUFSIZE 128
7482
#endif
7583

@@ -171,7 +179,8 @@ static void *__init_lib(void)
171179
DL_RESOLVE(posix_memalign);
172180
DL_RESOLVE(valloc);
173181

174-
//TODO: call backtrace here to init itself
182+
/* clock */
183+
g_ctx.clock_start = clock();
175184

176185
/* post-init status */
177186
if(!g_ctx.memlog_disabled)
@@ -180,6 +189,9 @@ static void *__init_lib(void)
180189
char path[256];
181190
char buf[LOG_BUFSIZE + sizeof(path)];
182191

192+
s = snprintf(buf, sizeof(buf), "# CLOCK-START %lu\n", g_ctx.clock_start);
193+
w = write(g_ctx.memlog_fd, buf, s);
194+
183195
s = snprintf(buf, sizeof(buf), "# PID %u\n", getpid());
184196
w = write(g_ctx.memlog_fd, buf, s);
185197

@@ -207,6 +219,7 @@ static void *__init_lib(void)
207219
g_ctx.stat.free);
208220
w = write(g_ctx.memlog_fd, buf, s);
209221

222+
210223
/* auto-disable trace if file is not open */
211224
if(w == -1 && errno == EBADF)
212225
g_ctx.memlog_disabled = true;
@@ -226,6 +239,8 @@ static void __attribute__ ((constructor))log_malloc2_init(void)
226239

227240
static void __fini_lib(void)
228241
{
242+
clock_t clck = clock();
243+
229244
/* check already finalized */
230245
if(!__sync_bool_compare_and_swap(&g_ctx.init_done,
231246
LOG_MALLOC_INIT_DONE, LOG_MALLOC_FINI_DONE))
@@ -247,6 +262,12 @@ static void __fini_lib(void)
247262

248263
/* maps out here, because dynamic libs could by mapped during run */
249264
copyfile(maps_head, sizeof(maps_head) - 1, g_maps_path, g_ctx.memlog_fd);
265+
266+
s = snprintf(buf, sizeof(buf), "# CLOCK-END %lu\n", clck);
267+
w = write(g_ctx.memlog_fd, buf, s);
268+
269+
s = snprintf(buf, sizeof(buf), "# CLOCK-DIFF %lu\n", clck - g_ctx.clock_start);
270+
w = write(g_ctx.memlog_fd, buf, s);
250271
}
251272

252273
if(g_ctx.statm_fd != -1)
@@ -266,6 +287,33 @@ static void __attribute__ ((destructor))log_malloc2_fini(void)
266287
/*
267288
* INTERNAL FUNCTIONS
268289
*/
290+
static inline size_t int2hex(unsigned long int num, char *str, size_t max_size)
291+
{
292+
size_t len = 0;
293+
const static char hex[] = { '0', '1', '2', '3', '4', '5', '6', '7',
294+
'8', '9' ,'a', 'b', 'c', 'd', 'e', 'f' };
295+
296+
do
297+
{
298+
str[len++] = hex[ num & 0xf ];
299+
num >>= 4;
300+
} while(num!=0);
301+
302+
unsigned int ii = 0;
303+
for(ii = 0; ii < (len / 2); ii++)
304+
{
305+
const unsigned int pos = len - ii - 1;
306+
const char w = str[ii];
307+
308+
str[ii] = str[pos];
309+
str[pos] = w;
310+
}
311+
str[len] = '\0';
312+
313+
return len;
314+
}
315+
316+
269317
static inline void log_trace(char *str, size_t len, size_t max_size, int print_stack)
270318
{
271319
int w;
@@ -280,9 +328,12 @@ static inline void log_trace(char *str, size_t len, size_t max_size, int print_s
280328
unw_cursor_t cursor;
281329
int unwind_count = 0;
282330

283-
unwind = (unw_getcontext(&uc) == 0);
284-
if(unwind)
285-
unwind = (unw_init_local(&cursor, &uc) == 0);
331+
if(print_stack)
332+
{
333+
unwind = (unw_getcontext(&uc) == 0);
334+
if(unwind)
335+
unwind = (unw_init_local(&cursor, &uc) == 0);
336+
}
286337
#else
287338
#ifdef HAVE_BACKTRACE
288339
int nptrs = 0;
@@ -304,15 +355,18 @@ static inline void log_trace(char *str, size_t len, size_t max_size, int print_s
304355
}
305356

306357
#ifdef HAVE_UNWIND
307-
while(unwind && unwind_count < LOG_MALLOC_BACKTRACE_COUNT
308-
&& unw_step(&cursor) > 0)
358+
while(print_stack && unwind && unwind_count < LOG_MALLOC_BACKTRACE_COUNT
359+
&& unw_step(&cursor) > 0
360+
&& max_size - len > (16 + 5))
309361
{
310362
unw_word_t ip = 0;
311363
unw_word_t offp = 0;
312364
size_t len_start = len;
313365

314366
unw_get_reg(&cursor, UNW_REG_IP, &ip);
315367

368+
#ifdef HAVE_UNWIND_DETAIL
369+
/* this harms performance */
316370
str[len++] = '*';
317371
str[len++] = '(';
318372
if(unw_get_proc_name(&cursor, &str[len], max_size - len - 1, &offp) == 0)
@@ -323,8 +377,13 @@ static inline void log_trace(char *str, size_t len, size_t max_size, int print_s
323377
}
324378
else
325379
len += -2;
380+
#endif
326381

327-
len += snprintf(&str[len], max_size - len - 1, "[0x%lx]", ip);
382+
str[len++] = '[';
383+
str[len++] = '0';
384+
str[len++] = 'x';
385+
len += int2hex(ip, &str[len], max_size - len - 1); // max 16 chars
386+
str[len++] = ']';
328387
str[len++] = '\n';
329388

330389
unwind_count++;

src/log-malloc2_internal.h

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -70,6 +70,7 @@ typedef struct log_malloc_ctx_s {
7070
int memlog_fd;
7171
int statm_fd;
7272
bool memlog_disabled;
73+
clock_t clock_start;
7374
#ifdef HAVE_LIBPTHREAD
7475
pthread_mutex_t loglock;
7576
#endif
@@ -82,7 +83,8 @@ typedef struct log_malloc_ctx_s {
8283
{0, 0, 0, 0, 0, 0, 0, 0}, \
8384
LOG_MALLOC_TRACE_FD, \
8485
-1, \
85-
false
86+
false, \
87+
0
8688

8789
#ifdef HAVE_LIBPTHREAD
8890
#define LOG_MALLOC_CTX_INIT \

0 commit comments

Comments
 (0)