3.13 Explanation of the Logfile Output

Most of time you will be using the logfile output from library as the sole information source for diagnosing problems in and getting statistics for your program.

1098918225: 3: Dmalloc version 'Version 5.5.2'
1098918225: 3: flags = 0x4f4e503, logfile '/tmp/dmalloc.log'
1098918225: 3: interval = 500, addr = 0, seen # = 0, limit = 0
1098918225: 3: starting time = 1098918225
1098918225: 3: process pid = 32406
1098918226: 4: WARNING: tried to free(0) from foo.c:708'
1098918228: 20: *** free: at 'unknown' pnt '0xed310080|s2': \
            size 12, alloced at 'bar.c:102'
1098918230: 50: ERROR: heap_check: free space was overwritten (err 67)
1098918230: 50: error details: checking free pointer
1098918230: 50: pointer '0x291c5' from 'unknown' prev access 'foo.c:787'

Here is a short example of some logfile information. Each of the lines are prefixed by the time (in epoch seconds since 1/1/1970) and the iteration or call count which is the number of times the library has been called from malloc, free, verify, etc.. In the above example, the first 5 log entries where written at epoch 1098918225 or `Wed Oct 27 19:03:45 2004 EST' and they were generated by the 3rd call to the library. See the `settings.dist' file entries to tune what elements appear on each line: LOG_TIME_NUMBER, LOG_ITERATION, LOG_PID, etc.. You can convert the epoch seconds to a date from the command line with the following perl code: perl -e 'print localtime($ARGV[0])."\n";' epoch-seconds-number

The first 5 lines of the sample logfile contain header information for all logfiles. They show the version number and URL for the library as well as all of the settings that the library is currently using. These settings are tuned using the dmalloc utility program. See section Dmalloc Utility Program. The 5th line of is the process-id that generated the logfile.

The 6th line in the above example is what causes the logfile to be opened and the header to be written. It is a warning that tells you that you tried to free a 0L pointer at a certain location. You can disable these warnings by setting `ALLOW_FREE_NULL_MESSAGE' to 0 in `settings.dist'.

Line 7 is an example of a transaction log that you get when you enable the log-trans debug token. See section Description of the Debugging Tokens. This line shows that a call to free was made from an unknown location. It is unknown because the file in question did not include `dmalloc.h' to get file/line-number information. The call to free was freeing the pointer address 0xed310080 which we have "seen" 2 times (s2). We saw the pointer when it was allocated and then we are seeing it again when it was freed. Because the library is reusing pointers (reclaiming freed memory) the seen count helps to track how many times a pointer was used. The last part of the line shows that the pointer to be freed was allocated by `bar.c' line 102.

Lines 8-10 is the next problem that the library caught and this one is an error. It happened 5 seconds from the start of the log (1098918230) and at the 50th call into the library. It shows that an allocation that had been freed then was overwritten. This may imply that someone tried to use memory after it was freed or that there was a loose pointer reference. The last two lines give more details about when the error was discovered, the address of the offending pointer, and when the pointer was previous accessed, in this case freed. To discover where this problem is happening, you can use a debugger. See section Using Dmalloc With a Debugger.

This document was generated by Gray Watson on May, 16 2007 using texi2html 1.76.

This work is licensed by Gray Watson under the Creative Commons Attribution-Share Alike 3.0 License.
This page should be W3C Valid XHTML and should work with most browsers.