Extracting useful info from FreeBSD malloc tracing
The FreeBSD version of the functions in the malloc() and free() family includes hooks that can dump “utrace” entries for the ktrace utility. The tracing features can be enabled by setting the “U” malloc option. The manpage of malloc says (among many other useful things):
TUNING
Once, when the first call is made to one of these memory allocation rou-
tines, various flags will be set or reset, which affects the workings of
this allocator implementation.
The ``name'' of the file referenced by the symbolic link named
<em>/etc/malloc.conf</em>, the value of the environment variable MALLOC_OPTIONS,
and the string pointed to by the global variable <em>_malloc_options</em> will be
interpreted, in that order, from left to right as flags.
Each flag is a single letter, optionally prefixed by a non-negative base
10 integer repetition count. For example, ``3N'' is equivalent to
``NNN''. Some flags control parameter magnitudes, where uppercase
increases the magnitude, and lowercase decreases the magnitude. Other
flags control boolean parameters, where uppercase indicates that a behav-
ior is set, or on, and lowercase means that a behavior is not set, or
off. [...]
U Generate ``utrace'' entries for ktrace(1), for all operations.
Consult the source for details on this option.
This means that when you run a program under ktrace you can gather lines of malloc() and free() trace info like the following:
$ <strong>env MALLOC_OPTIONS='U' ktrace ./a.out</strong><br />$ <strong>kdump -tu -f ktrace.out</strong><br /> 11981 a.out USER malloc_init()<br /> 11981 a.out USER 0x8101080 = malloc(100)<br /> 11981 a.out USER 0x8103300 = malloc(600)<br /> 11981 a.out USER free(0x8103300)
This short trace was collected by running a compiled version of the following C program:
<em><strong>#include</strong> <stdlib.h></em><br /><br /><strong>int</strong><br /><em>main</em>(<strong>void</strong>)<br />{<br /> <strong>void</strong> *p;<br /><br /> p = calloc(1, 100);<br /><em><strong>#ifndef</strong> LEAK</em><br /> free(p);<br /><em><strong>#endif</strong></em><br /> posix_memalign(&p, 16, 600);<br /> free(p);<br /> <strong>return</strong> 0;<br />} With a program of this size, it’s quite easy to spot the memory leak; even without ktrace info. For larger programs, there maybe thousands of trace lines to analyze. A single invocation of the find utility may generate hundreds of thousands of ktrace records:
$ <strong>env MALLOC_OPTIONS='U' ktrace find $HOME/mail > /dev/null</strong><br />$ <strong>kdump -tu -f ktrace.out | wc -l</strong><br /> 244813<br />
Trying to match the allocation and free calls in a trace with so many entries can be tedious, error prone and very boring, so I wrote a little Python script to help me do it.
The script can read a kdump trace from its standard input, or from a list of files. When run without arguments it tries to read a stream of trace messages from standard input. It then tries to match the allocation records with the free records, using the memory address of each trace line. If there are no memory leaks, it does not print anything and it exits:
$ <strong>kdump -T -f ktrace.out | ./alloctrace.py</strong><br />$
The script is doing its work silently, searching for patterns in the output of kdump, and keeping a record of the malloc/free “utrace” information it can find. You can see what it’s doing by bumping the script’s verbosity level a bit:
$ <strong>kdump -T -f ktrace.out | ./alloctrace.py -v</strong><br /># Bumping verbosity level to 1<br /># analyzing trace from <stdin><br />trace: allocated 100 bytes at 0x8101080<br />trace: freed 100 bytes at 0x8101080<br />trace: allocated 600 bytes at 0x8101300<br />trace: freed 600 bytes at 0x8101300<br />$
When the script reaches the end of a trace and it detects that there are some allocation records that haven’t been matched by a free record in the trace, it prints a list of all the “leaked” memory areas:
$ <strong>kdump -T -f ktrace.out | ./alloctrace.py</strong><br />--- memory leaks ---<br />leaked 100 bytes at 0x8101080<br /> utrace record:<br /> 12146 a.out 1224066908.225938 USER 0x8101080 = malloc(100)<br />total leaked bytes = 100<br />$
By bumping the verbosity level, it also prints the utrace records as it reads them from the trace:
$ <strong>kdump -T -f ktrace.out | ./alloctrace.py -v</strong><br /># Bumping verbosity level to 1<br /># analyzing trace from <stdin><br />trace: allocated 100 bytes at 0x8101080<br />trace: allocated 600 bytes at 0x8103300<br />trace: freed 600 bytes at 0x8103300<br />--- memory leaks ---<br />leaked 100 bytes at 0x8101080<br /> utrace record:<br /> 12146 a.out 1224066908.225938 USER 0x8101080 = malloc(100)<br />total leaked bytes = 100<br />$ <strong>kdump -T -f ktrace.out | ./alloctrace.py -vv</strong><br /># Bumping verbosity level to 1<br /># Bumping verbosity level to 2<br /># analyzing trace from <stdin><br /># precompiling alloc-re<br /># precompiling free-re<br /># initializing address allocation map<br /># initializing address cache<br />trace: allocated 100 bytes at 0x8101080<br /># utrace record:<br /># 12146 a.out 1224066908.225938 USER 0x8101080 = malloc(100)<br />trace: allocated 600 bytes at 0x8103300<br /># utrace record:<br /># 12146 a.out 1224066908.226173 USER 0x8103300 = malloc(600)<br />trace: freed 600 bytes at 0x8103300<br /># utrace record:<br /># 12146 a.out 1224066908.226349 USER free(0x8103300)<br />--- memory leaks ---<br />leaked 100 bytes at 0x8101080<br /> utrace record:<br /> 12146 a.out 1224066908.225938 USER 0x8101080 = malloc(100)<br />total leaked bytes = 100<br />$
Being able to pinpoint the time that a buffer was allocated may be helpful when trying to locate the place in kdump output where the leaked memory was allocated:
$ <strong>kdump -T -f ktrace.out | ./alloctrace.py</strong><br />--- memory leaks ---<br />leaked 100 bytes at 0x8101080<br /> utrace record:<br /> 12146 a.out 1224066908.225938 USER 0x8101080 = malloc(100)<br />total leaked bytes = 100<br />$ <strong>kdump -T -f ktrace.out | fgrep -n 1224066908.225938</strong><br />272: 12146 a.out 1224066908.225938 USER 0x8101080 = malloc(100)<br />$
In this case, we know that we can start looking near line 272 of the trace. This is the place where the leaked buffer was allocated. By skimming through nearby trace output, we may be able to understand a bit more about the location of the leak in the source too :-)
A short Python script cannot really replace more advanced memory debugging tools, like Valgrind, dmalloc, or a combination of libumem and mdb (my favorite Solaris tools), but having something that can quickly run through a huge ktrace log and show a quick summary of memory leaks is nice. What a script like this can do is to serve as a first-level check that a program isn’t leaking memory like mad.
The script itself
The script source is available online at:
http://people.freebsd.org/~keramida/alloctrace.py.txt
Its source is small enough that I am including it here too, for print versions of this article:
#!/usr/bin/env python<br /><br /># A short Python script to analyze kdump output for the `utrace'<br /># debugging output of FreeBSD malloc.<br /><br /># Copyright (c) 2008 Giorgos Keramidas <keramida@FreeBSD.org><br /># All rights reserved.<br />#<br /># Redistribution and use in source and binary forms, with or without<br /># modification, are permitted provided that the following conditions<br /># are met:<br /># 1. Redistributions of source code must retain the above copyright<br /># notice, this list of conditions and the following disclaimer.<br /># 2. Redistributions in binary form must reproduce the above copyright<br /># notice, this list of conditions and the following disclaimer in the<br /># documentation and/or other materials provided with the distribution.<br />#<br /># THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND<br /># ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE<br /># IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE<br /># ARE DISCLAIMED. IN NO EVENT SHALL THE AUTHOR OR CONTRIBUTORS BE LIABLE<br /># FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL<br /># DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS<br /># OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)<br /># HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT<br /># LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY<br /># OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF<br /># SUCH DAMAGE.<br /><br /><strong>import</strong> errno<br /><strong>import</strong> getopt<br /><strong>import</strong> re<br /><strong>import</strong> sys<br /><strong>import</strong> os<br /><br /># -------------------- script options ----------------------------------<br /><br />verbose = <em>None</em> # Run in `quiet' mode by default.<br /><br /># -------------------- useful functions --------------------------------<br /><br /><strong>def</strong> ignoremsg(msg=<em>None</em>):<br /> <em>"""Print nothing. Ignore the message string passed to us.<br /> This is useful as a `callback' that uses the same function stub<br /> as message() but prints nothing."""</em><br /> <strong>return</strong> <em>None</em><br /><br /><strong>def</strong> message(msg=<em>None</em>):<br /> <em>"""Print an optional `msg' message string to our standard error<br /> stream. Note that a newline is appended automatically to the<br /> message string, as if it was displayed with print(), and no<br /> exceptions are captured by message()."""</em><br /> <strong>if</strong> msg:<br /> s = "%s\n" % (msg)<br /> sys.stderr.write(s)<br /> sys.stderr.flush()<br /> <strong>return</strong> <em>None</em><br /><br /><strong>def</strong> error(code, msg=<em>None</em>):<br /> <em>"""Print `msg' as an optional error message string, and die with an<br /> error of `code'."""</em><br /> <strong>if</strong> msg:<br /> s = '%s: error: %s' % (progname, msg)<br /> message(s)<br /> sys.exit(code)<br /><br /><strong>def</strong> warning(msg=<em>None</em>):<br /> <em>"""Print `msg' as an optional warning string."""</em><br /> <strong>if</strong> msg:<br /> s = '%s: warning: %s' % (progname, msg)<br /> message(s)<br /> <strong>return</strong> <em>None</em><br /><br /><strong>def</strong> debug(level=1, msg=<em>None</em>):<br /> <em>"""Print an optional debugging message `msg', when the verbosity<br /> level `verbose' of the script exceeds or is equal to `level'<br /> (default=1)."""</em><br /> <strong>if</strong> verbose <strong>and</strong> verbose >= level <strong>and</strong> msg:<br /> message("# " + msg)<br /><br /># -------------------- main script body --------------------------------<br /><br /># Precompiled regular expressions, to match the `utrace' output format<br /># of the kdump utility, and extract bits of the allocation or memory<br /># freeing trace entries. The output of `kdump' looks like this:<br />#<br /># 42246 a.out 1224038211.153343 USER malloc_init()<br /># 42246 a.out 1224038211.153434 USER 0x8101080 = malloc(100)<br /># 42246 a.out 1224038211.153453 USER 0x8103300 = malloc(600)<br /># 42246 a.out 1224038211.153462 USER free(0x8103300)<br />allocre = <em>None</em><br />freere = <em>None</em><br /><br /><strong>def</strong> loadtrace(fp):<br /> <em>"""Read `kdump' output from the open file passed as `fp', and try to<br /> detect memory leaks by matching the allocation entries with the<br /> memory freeing trace entries."""</em><br /><br /> <strong>global</strong> allocre, freere<br /> <strong>if</strong> <strong>not</strong> allocre:<br /> <strong>try:</strong><br /> debug(2, "precompiling alloc-re")<br /> allocre = re.compile(r'^.*\s+USER\s+.*(0x[0-9a-fA-F]+)\s+=\s+malloc\((\d+)\)\s* 4 Comments »
except Exception, inst:
error(1, "invalid regular expression: %s" % inst)
if not freere:
try:
debug(2, "precompiling free-re")
freere = re.compile(r'^.*\s+USER\s+free\((0x[0-9a-fA-F]+)\)\s*
4 Comments »
-
Update: I’ve refactored a bit the main loadtrace() body, and added realloc() matching too. The new script is now online at:
-
-
-
way cool stuff.
DTrace on Solaris permits similar things.Comment by Konstantinos Koukopoulos — 2008-11-06 @ 10:02:35 |
except Exception, inst:
error(1, "invalid regular expression: %s" % inst)
if verbose and verbose > 0:
log = message
else:
log = ignoremsg
debug(2, "initializing address allocation map")
amap = {} # Empty allocation map
debug(2, "initializing address cache")
acache = {}
for l in fp.readlines():
l = l.rstrip('\r\n')
debug(4, "line \"%s\"" % l)
m = allocre.match(l)
if m:
debug(3, "alloc line: %s" % l)
addr = int(m.group(1), 0)
size = int(m.group(2), 0)
if addr in amap:
error(1, "memory at 0x%x allocated already" % addr)
amap[addr] = (size, l)
acache[addr] = True
log("trace: allocated %d bytes at 0x%x" % (size, addr))
debug(2, " utrace record:")
debug(2, " %s" % l)
m = freere.match(l)
if m:
debug(3, "free line: %s" % l)
addr = int(m.group(1), 0)
if addr in amap:
(size, msg) = amap.pop(addr)
log("trace: freed %d bytes at 0x%x" % (size, addr))
debug(2, " utrace record:")
debug(2, " %s" % l)
else:
if addr in acache:
log("warning: double-free at 0x%x" % addr)
else:
log("warning: free of non-malloced region at 0x%x" % addr)
debug(2, " utrace record:")
debug(2, " %s" % l)
leaks = amap.keys()
if len(leaks) == 0:
debug(2, "no leaks found; address map empty")
return None
message("--- memory leaks ---");
leakedbytes = 0
for addr in leaks:
(size, msg) = amap[addr]
message("leaked %d bytes at 0x%x" % (size, addr))
message(" utrace record:")
message(" %s" % msg)
leakedbytes += size
message("total leaked bytes = %d" % leakedbytes)
return leakedbytes
if __name__ == '__main__':
try:
opts, args = getopt.getopt(sys.argv[1:], 'v')
except getopt.GetoptError, err:
usage()
# Go through the list of command-line options, and tune the globals
# which affect the behavior of the script accordingly.
for o, v in opts:
if o == '-v':
verbose = verbose and (verbose + 1) or 1
debug(1, "Bumping verbosity level to %d" % verbose)
else:
assert False, "Unhandled option `%s'" % o
try:
if len(args) == 0:
debug(1, "analyzing trace from
loadtrace(sys.stdin)
else:
for fname in args:
try:
debug(1, "analyzing trace `%s'")
loadtrace(file(fname))
except IOError, inst:
if inst.errno == errno.ENOENT:
print "%s: %s" % (fname, str(inst))
else:
raise
except KeyboardInterrupt, inst:
message("Interrupted.")
sys.exit(0)
4 Comments »
-
Update: I’ve refactored a bit the main loadtrace() body, and added realloc() matching too. The new script is now online at:
-
-
-
way cool stuff.
DTrace on Solaris permits similar things.Comment by Konstantinos Koukopoulos — 2008-11-06 @ 10:02:35 |
Update: I’ve refactored a bit the main loadtrace() body, and added realloc() matching too. The new script is now online at:
http://people.freebsd.org/~keramida/alloctrace-2.py.txt
Comment by keramida — 2008-10-15 @ 03:21:30 |
[...] Tepper has added (based on this FreeBSD work) the ability to “parse the utrace(2) entries generated by malloc(3) in a more human-readable [...]
Pingback by Parsing utrace(2) entries · DragonFly BSD Digest — 2008-10-15 @ 05:35:13 |
[...] encore une fois eux, nous dégotent un petit tutoriel d’un commiter (Giorgos Keramidas) qui nous explique comment employer ktrace pour suivre l’utilisation mémoire d’une application, ainsi [...]
Pingback by Ne perdez pas la mémoire at FreeBSD-fr: Les nouvelles du géant en français — 2008-10-17 @ 09:35:01 |
way cool stuff.
DTrace on Solaris permits similar things.
Comment by Konstantinos Koukopoulos — 2008-11-06 @ 10:02:35 |