#! /usr/bin/less ################################################################################ Program : log-malloc2 (library) Version : 0.4.0 Purpose : Malloc logging library with backtrace and byte-exact memory tracking. License : GNU GPL v3 (see file COPYING) GNU LGPL v3 (see file COPYING-LGPL) Author : Samuel Behan <_samuel_._behan_(at)_dob_._sk> (c) 2011-2015 Web : http://devel.dob.sk/log-malloc2 http://blog.dob.sk/category/devel/log-malloc2 (howto, tutorial) ################################################################################ --------- - ABOUT - --------- log-malloc2 is library for tracking memory functions calls, that can be preloaded using LD_PRELOAD or even directly linked to your program. It also provides simple api to programaticaly check current memory usage (bytes requested) intended for testing purposes. --- This library is partialy based on log-malloc library, hence the name log-malloc2 - and I'm too lazy to figure out better name. I've taken some ideas from this library, but it's completely rewriten to make backtracing work also on 64bit system, and to provide also additional usefull informations regarding allocated memory. ------------ - FEATURES - ------------ * logging to file descriptor 1022 (if opened) * call stack backtrace (via GNU backtrace() or libunwind) * requested memory tracking (byte-exact) * allocated memory tracking (byte-exact - using malloc_usable_size()) * process memory status tracking (from /proc/self/statm) * call counting * thread safe (used also to prevent log mixing) * optional C API for runtime memory usage checking --------- - USAGE - --------- log-malloc -o /tmp/program.log command args OR LD_PRELOAD=./liblog-malloc2.so command args ... 1022>/tmp/program.log This generates log-malloc trace file, tracking all memory operations and associated stack backtraces that helps to identify source file/line that made that memory operation. Having program compiled with debug information and -rdynamic makes backtrace call stack better readable. Aferwards, you can use backtrace2line script or addr2line tool from GNU binutils to convert backtrace addresses into exact source code line numbers (if using addr2line you have to deal with ASLR yourselves). If trace file descriptor is not opened for writing on library initialisation, trace output is automatically disabled, and should not further harm program performance anyhow. This package provides also additional scripts, that will help you to deal with log-malloc2 trace: * backtrace2line Script to automatically convert backtrace in files and line numbers. Can also deal with ASLR randomized addresses. * log-malloc-findleak Script to discover possible program memory leaks from trace file * log-malloc-trackusage Script to track program memory usage over time. These scripts can be also used as perl packages, because they export functions to parse and analyse trace file or convert backtraces (modulino concept). --------- - C API - --------- log-malloc2.h provides simple C API functions (ideal for testing) that can be used if it is directly linked to a program at compile/link time. Warning: Such a usage is not recommended in production environment! Memory tracking and call counting use memory bariers, that may degrade application performance. size_t log_malloc_get_usage(void) Get actual program memory usage in bytes void log_malloc_trace_enable(void) Enable trace messages to be printed to trace fd. void log_malloc_trace_disable(void) Disable trace messages. int log_malloc_trace_printf(const char *fmt, ...) Printf smth. to trace fd (message size is limited to 1024 bytes). LOG_MALLOC_SAVE(name, trace) [MACRO] Creates savepoint with given _name_ that stores actual memory usage. If _trace_ is true, message will be logged to trace fd. LOG_MALLOC_UPDATE(name, trace) [MACRO] Updates actual memory usage in savepoint with given _name_. If _trace_ is true, trace message will be logged to trace fd. LOG_MALLOC_COMPARE(name, trace) [MACRO] Compares actual memory usage with the saved one under given _name_. If _trace_ is true, trace message will be logged to trace fd. Call returns memory usage difference (size_t). LOG_MALLOC_ASSERT(name, iter) [MACRO] ASSERT with fail, if actual memory usage differs from the one saved in savepoint. _iter_ can specify that assertion should be checked first after given number of LOG_MALLOC_SAVE() iterations. LOG_MALLOC_NDEBUG [MACRO] If defined, above macros will generate no code. ---------------- - C INLINE API - ---------------- log-malloc2_util.h provides for convenience, few fully inlined functions, that can be used without linking library itself. void log_malloc_backtrace_init(void) Pre-initializes backtrace() function, to avoid later memory alocations. Use of this function is optional. ssize_t log_malloc_backtrace(int fd) Generate current backtrace including process memory map (/proc/self/maps) to make backtrace symbol conversion easier. Generated output can be directly pasted to backtrace2line script. -------------------- - PERFORMANCE TIPS - -------------------- * Ensure that libunwind is enabled Libunwind generates backtrace approx. 2x faster than GNU backtrace(). With libunwind there is only single write() used for logging (compared to at least 2 calls when using backtrace()). Futhermore, there is no protective mutex locking needed, what should reduce waits in multi-threaded programs. * Log to tmpfs, or other FS that handles write operation effectively If traced application intensively allocates memory, consider logging to tmpfs because writting to trace fd is the slowest operation, that might be in addition protected by a mutex (if GNU backtrace is used), thus serializing multithreaded memory allocations. --------------------------------- - TRACKED FUNCTIONS & INTERNALS - --------------------------------- * malloc * realloc * calloc Note: library changes passed parameters from calloc(nmemb, size) to calloc(1, nmemb*size). Allocated memory is exactly the same but there might(?) appear some problem due to this change. * memalign * posix_memalign * valloc * free Note: call to free are not backtraced, also free(NULL) calls are completely ignored. Library allocates additional 32 bytes (due to structure alignment) per every allocated memory. This is necessary to make byte-exact memory tracking possible. This memory is placed in front of allocated memory and stores size of allocated memory (1 x size_t) and check bits (1 x size_t) for allocated size number and real-aligned allocated memory size (1 x size_t). These data are also used to distinguish memory allocated by this library, and memory that has been allocated by something else (whatever it was, you can identify it by appended '!f' when free()-ing). This functionality makes log-malloc2 library less resistant against random memory overwrites, that will destroy library internal data (especially by realloc/free), but incorrect memory overwrites are anyway bad, and this makes them only better recognizable. Library uses malloc_usable_size() function (if available) to determine how much memory has been really allocated by libc. Allocated memory differs from requested memory, because alocated memory blocks are usualy aligend to some power of 2. Note: Allocated memory status (MEM-STATUS) might and will differ from numbers you will see in top/ps or statm data, because memory is allocated in blocks that are usually greater than requested memory, but it might be relatively close to MEM-STATUS-ALIGNED. DuckDuckGo it ;) ---------- - OUTPUT - ---------- Logfile has following structure + FUNCTION MEM-CHANGE MEM-IN? MEM-OUT? (FUNCTION-PARAMS) [MEM-STATUS:MEM-STATUS-USABLE] #STATM-DATA BACKTRACE ... ... + FUNCTION.... ... # ADDITIONAL-DATA ... Legend: FUNCTION - called function name (malloc/realloc/free...) MEM-CHANGE - bytes allocated/deallocated MEM-IN - (optional) input memory pointer MEM-OUT - (optional) (re)allocated memory pointer MEM-STATUS - actually allocated memory using functions MEM-STATUS-USABLE - sum of allocated memory reported by malloc_usable_size FUNCTION-PARAMS - parameter that has been passed to function STATM-DATA - copy of /proc/self/statm content ADDITIONAL-DATA - additional runtime data, like PID, CWD, MAPS content ------------------ - EXAMPLE OUTPUT - ------------------ $ log-malloc.pl -o - ./examples/leak-01 *** log-malloc trace-fd = 1022 *** + malloc 53 0x7f9bff564080 [85:160]! + calloc 1182 0x7f9bff5640e0 [1267:1384] (1182 1)! + malloc 53 0x7f9bff5645b0 [1320:1472]! + malloc 56 0x7f9bff564610 [1376:1560]! + calloc 360 0x7f9bff564670 [1736:1952] (15 24)! + calloc 32 0x7f9bff564030 [32:72] (1 32) #3183 168 131 1 0 84 0 /lib64/libdl.so.2(+0x1960)[0x7f9bfcfa8960] /lib64/libdl.so.2(dlsym+0x5a)[0x7f9bfcfa843a] /home/sam/devel/log-malloc2/scripts/../.libs/liblog-malloc2.so(+0x12e3)[0x7f9bfd7882e3] /lib64/ld-linux-x86-64.so.2(+0xfa0b)[0x7f9bfd99ba0b] /lib64/ld-linux-x86-64.so.2(+0xfb1c)[0x7f9bfd99bb1c] /lib64/ld-linux-x86-64.so.2(+0x140a)[0x7f9bfd98d40a] /lib64/libdl.so.2(+0x13a0)[0x7f9bfcfa83a0] # PID 23451 # EXE /home/sam/devel/log-malloc2/examples/leak-01 # CWD /home/sam/devel/log-malloc2 + INIT [1736:1952] malloc=3 calloc=3 realloc=0 memalign=0/0 valloc=0 free=0 + malloc 2000 0x7f9bff564800 [3736:3992] #3183 168 131 1 0 84 0 ./examples/leak-01(main+0x32)[0x7f9bfdbb1af2] /lib64/libc.so.6(__libc_start_main+0x11b)[0x7f9bfd3f01cb] ./examples/leak-01(+0x9a9)[0x7f9bfdbb19a9] [0x0] + malloc 100 0x7f9bff565000 [3836:4128] #3183 168 131 1 0 84 0 ./examples/leak-01(main+0x40)[0x7f9bfdbb1b00] /lib64/libc.so.6(__libc_start_main+0x11b)[0x7f9bfd3f01cb] ./examples/leak-01(+0x9a9)[0x7f9bfdbb19a9] [0x0] + free -100 0x7f9bff565000 [3736:3992] #3183 168 131 1 0 84 0 + FINI [3736:3992] malloc=5 calloc=3 realloc=0 memalign=0/0 valloc=0 free=1 # FILE /proc/self/maps 7f9bfcd90000-7f9bfcda6000 r-xp 00000000 fe:02 911050 /usr/lib64/gcc/x86_64-pc-linux-gnu/4.8.3/libgcc_s.so.1 7f9bfcda6000-7f9bfcfa5000 ---p 00016000 fe:02 911050 /usr/lib64/gcc/x86_64-pc-linux-gnu/4.8.3/libgcc_s.so.1 7f9bfcfa5000-7f9bfcfa6000 r--p 00015000 fe:02 911050 /usr/lib64/gcc/x86_64-pc-linux-gnu/4.8.3/libgcc_s.so.1 7f9bfcfa6000-7f9bfcfa7000 rw-p 00016000 fe:02 911050 /usr/lib64/gcc/x86_64-pc-linux-gnu/4.8.3/libgcc_s.so.1 7f9bfcfa7000-7f9bfcfaa000 r-xp 00000000 fe:02 819448 /lib64/libdl-2.19.so 7f9bfcfaa000-7f9bfd1a9000 ---p 00003000 fe:02 819448 /lib64/libdl-2.19.so 7f9bfd1a9000-7f9bfd1aa000 r--p 00002000 fe:02 819448 /lib64/libdl-2.19.so 7f9bfd1aa000-7f9bfd1ab000 rw-p 00003000 fe:02 819448 /lib64/libdl-2.19.so 7f9bfd1ab000-7f9bfd1c5000 r-xp 00000000 fe:02 818913 /lib64/libpthread-2.19.so 7f9bfd1c5000-7f9bfd3c5000 ---p 0001a000 fe:02 818913 /lib64/libpthread-2.19.so 7f9bfd3c5000-7f9bfd3c6000 r--p 0001a000 fe:02 818913 /lib64/libpthread-2.19.so 7f9bfd3c6000-7f9bfd3c7000 rw-p 0001b000 fe:02 818913 /lib64/libpthread-2.19.so 7f9bfd3c7000-7f9bfd3cb000 rw-p 00000000 00:00 0 7f9bfd3cb000-7f9bfd57d000 r-xp 00000000 fe:02 819451 /lib64/libc-2.19.so 7f9bfd57d000-7f9bfd77d000 ---p 001b2000 fe:02 819451 /lib64/libc-2.19.so 7f9bfd77d000-7f9bfd781000 r--p 001b2000 fe:02 819451 /lib64/libc-2.19.so 7f9bfd781000-7f9bfd783000 rw-p 001b6000 fe:02 819451 /lib64/libc-2.19.so 7f9bfd783000-7f9bfd787000 rw-p 00000000 00:00 0 7f9bfd787000-7f9bfd78b000 r-xp 00000000 fe:02 14619 /home/sam/devel/log-malloc2/.libs/liblog-malloc2.so.1.0.0 7f9bfd78b000-7f9bfd98a000 ---p 00004000 fe:02 14619 /home/sam/devel/log-malloc2/.libs/liblog-malloc2.so.1.0.0 7f9bfd98a000-7f9bfd98b000 r--p 00003000 fe:02 14619 /home/sam/devel/log-malloc2/.libs/liblog-malloc2.so.1.0.0 7f9bfd98b000-7f9bfd98c000 rw-p 00004000 fe:02 14619 /home/sam/devel/log-malloc2/.libs/liblog-malloc2.so.1.0.0 7f9bfd98c000-7f9bfd9ae000 r-xp 00000000 fe:02 818908 /lib64/ld-2.19.so 7f9bfdb99000-7f9bfdb9d000 rw-p 00000000 00:00 0 7f9bfdbad000-7f9bfdbae000 rw-p 00000000 00:00 0 7f9bfdbae000-7f9bfdbaf000 r--p 00022000 fe:02 818908 /lib64/ld-2.19.so 7f9bfdbaf000-7f9bfdbb0000 rw-p 00023000 fe:02 818908 /lib64/ld-2.19.so 7f9bfdbb0000-7f9bfdbb1000 rw-p 00000000 00:00 0 7f9bfdbb1000-7f9bfdbb2000 r-xp 00000000 fe:02 15340 /home/sam/devel/log-malloc2/examples/leak-01 7f9bfddb1000-7f9bfddb2000 r--p 00000000 fe:02 15340 /home/sam/devel/log-malloc2/examples/leak-01 7f9bfddb2000-7f9bfddb3000 rw-p 00001000 fe:02 15340 /home/sam/devel/log-malloc2/examples/leak-01 7f9bff564000-7f9bff585000 rw-p 00000000 00:00 0 [heap] 7fffb5471000-7fffb5493000 rw-p 00000000 00:00 0 [stack] 7fffb54cf000-7fffb54d1000 r-xp 00000000 00:00 0 [vdso] ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0 [vsyscall]