GLIBC: debugging memory leaks: how to interpret output of mtrace()

Question

I’m trying to debug a memory leak problem. I’m using mtrace() to get a malloc/free/realloc trace. I’ve ran my prog and have now a huge log file. So far so good. But I have problems interpreting the file. Look at these lines:

@ /usr/java/ibm-java2-x86_64-50/jre/bin/libj9prt23.so:[0x2b270a384a34] + 0x1502570 0x68
@ /usr/java/ibm-java2-x86_64-50/jre/bin/libj9prt23.so:[0x2b270a384a34] + 0x1502620 0x30
@ /usr/java/ibm-java2-x86_64-50/jre/bin/libj9prt23.so:[0x2b270a384a34] + 0x2aaab43a1700 0xa80
@ /usr/java/ibm-java2-x86_64-50/jre/bin/libj9prt23.so:[0x2b270a384a34] + 0x1501460 0xa64

The strange about this is that one call (same return address) is responsible for 4 allocations.

Even stranger:

@ /usr/java/ibm-java2-x86_64-50/jre/bin/libj9prt23.so:[0x2b270a384a34] + 0x2aaab43a1700 0xa2c
…
@ /usr/java/ibm-java2-x86_64-50/jre/bin/libj9prt23.so:[0x2b270a384a34] + 0x2aaab43a1700 0xa80

Between those two lines the block 0x2aaab43a1700 is never being freed.

Does anyone know how to explain this? How could one call result in 4 allocations? And how could malloc return an address which was already allocated previously?

edit 2008/09/30: The script to analyze the mtrace() output provided by GLIBC (mtrace.pl) isn't of any help here. It will just say: Alloc 0x2aaab43a1700 duplicate. But how could this happen?

Answer 1

One possible explanation is that the same function is allocating different buffer sizes? One such example is strdup.

For the second question, it is possible that the runtime is allocating some "static" scratch area which is not intended to be freed until the process is terminated. And at that point, the OS will clean-up after the process anyway.

Think about it this way: in Java, there are no destructors, and no guarantees that finalization will be ever called for any object.

Answer 2

Try running your app under valgrind. It might give you a better view about what is actually being leaked.

Answer 3

You're looking at the direct output of mtrace, which is extremely confusing and counterintuitive. Luckily, there is a perl script (called mtrace, found within glibc-utils) which can very easily help the parsing of this output.

Compile your build with debugging on, and run mtrace like such:

$ gcc -g -o test test.c
$ MALLOC_TRACE=mtrace.out ./test
$ mtrace test mtrace.out

Memory not freed:
-----------------
   Address     Size     Caller
0x094d9378    0x400  at test.c:6

The output should be a lot easier to digest.

Answer 4

The function that is allocating the memory is being called more than once. The caller address points to the code that did the allocation, and that code is simply being run more than once.

Here is an example in C:

void *allocate (void)
{
  return (malloc(1000));
}

int main()
{
  mtrace();
  allocate();
  allocate();
}

The output from mtrace is:

Memory not freed:
-----------------
           Address     Size     Caller
0x0000000000601460    0x3e8  at 0x4004f6
0x0000000000601850    0x3e8  at 0x4004f6

Note how the caller address is identical? This is why the mtrace analysing script is saying they are identical, because the same bug is being seen more that once, resulting in several memory leaks.

Compiling with debugs flags (-g) is helpful if you can:

Memory not freed:
-----------------
           Address     Size     Caller
0x0000000000601460    0x3e8  at /home/andrjohn/development/playground/test.c:6
0x0000000000601850    0x3e8  at /home/andrjohn/development/playground/test.c:6