Re: mtrace perl tool reporting "+ 0x000001003c393dc0 Alloc 3183 duplicate: 0x3fffaa678d08 /lib64/libntirpc.so.1.3:[0x3fffaa678d08]"

[Carlos O'Donell <carlos at redhat dot com>]

On 2/19/19 6:15 PM, DJ Delorie wrote:
> 
> Malahal Naineni <malahal@gmail.com> writes:
>> I am using matrace to find out a memory leak in a long running server
>> application. Why do I get the above warning/error? Using
>> glibc-2.17-222.el7 package from Redhat if that matters. The
>> applications is a multi-threaded application.
> 
> This basically says "you've already allocated this, and I didn't see a
> free()" which *seems* like malloc() is returning the same address twice.
> In reality, it's more likely (assuming something hasn't actually broken)
> that threads are doing malloc operations in one order, but reporting
> them in a different order, so the mtrace tool sees a malloc() return a
> pointer just before the free() that had free'd it, instead of
> free-then-malloc.
> 
> i.e. the program does this:
> 
> x = malloc(sz);
> free (sz);
> x = malloc(sz); /* returns same value */
> 
> but the *logs* say something like this:
> 
> + MALLOC 0x1234
> + MALLOC 0x1234
> - FREE 0x1234
> 
> Having said that, something could be broken for any number of weird
> reasons (example: a lost record, data corruption, etc), and knowing for
> sure what the problem is would require poring over your logs for hours
> trying to figure out what actually happened.

That is odd. The serializing lock in all the tr_*hook functions should
ensure that you see the correct order. One possibility is a thread crash
or hang in free/tr_freehook.

Only in the modern tracer we wrote (not mtrace) can you get trace
inversion because we don't force a total global order, we just dump
as fast as we can into the trace buffer using atomics and sort it
later.

The only real solution is to go through your trace event by event and
figure out what's wrong.

-- 
Cheers,
Carlos.