Chris Quenelle's Weblog
Thoughts on developer tools.

Friday May 18, 2007

Using dbx and libumem to find memory problems

Update: There is a new version of umem.dbx here (Solaris 9 support) Download it here.

I implemented a spiffy little dbx module to give basic access to libumem debugging features a while back, but I haven't gotten much feedback on it.  Think of this blog entry like a Dunk Tank at the carnival. Throw a blog comment at me (like a bug or an RFE) and make me add some new features to my libumem dbx module.

Here are things I know to be true:

• developers prefer dbx to mdb (unless you're hacking on the kernel)
• the RTC feature in Sun Studio is slow and sometimes buggy
• memory allocation and access bugs are NASTY to track down
• nobody has requested any new features for the libumem module

(dbx) source umem.dbx
(dbx) alias u=umem

(dbx) u start
Enabling libumem debugging

(dbx) cc -g t.c
(dbx) debug a.out
(dbx) list 1,$
    1   #include <malloc.h>
    2   int main()
    3   {
    4        char * p;
    5        p = malloc(1);
    6        p = malloc(1);
    7        p = malloc(1);
    8        free(p);
    9        p++;
   10        // this free will cause an error in libumem
   11        // if checking is on, because it's a bad free
   12        free(p);
   13   }
   14

(dbx) run
signal ABRT (Abort) in __lwp_kill at 0xff2bd5ec
0xff2bd5ec: __lwp_kill+0x0008:  bcc,a,pt  %icc,__lwp_kill+0x18  ! 0xff2bd5fc
Current function is main
   12        free(p);

(dbx) print p
p = 0x5bfa9 "\xad\xbe\xef\xde\xad\xbe\xef\xfe\xed\xfa\xce\xfe\xed\xfa\xce"

(dbx) u findblock 0x5bfa9

Building umem_syms helper library.
Address 0x5bfa9 is inside the umem block at 0x5bfa0.
   This corresponds to the malloc block at 0x5bfa8.

# So we can see that the pointer we tried to free points into
# the middle of a block.

# Let's ask for a history of the umem block that caused umem to barf.

(dbx) u bhist 0x5bfe0

=================================================================
       Log Rec Addr          Block Addr   Thrd         Timestamp
       ------------          ----------   ----         ---------
            0x320c8             0x5bfa0    1     0xbda1d488b8260
0x107d0 : in `a.out`_start   /* No debugging info */
0x10c1c : in `a.out`t.c`main at "t.c":7
0xff36aeb4 : in `libumem.so.1`malloc   /* No debugging info */
0xff36e2d0 : in `libumem.so.1`_umem_alloc   /* No debugging info */
0xff36de8c : in `libumem.so.1`_umem_cache_alloc   /* No debugging info */
=================================================================
       Log Rec Addr          Block Addr   Thrd         Timestamp
       ------------          ----------   ----         ---------
            0x3212c             0x5bfa0    1     0xbda1d488ba010
0x107d0 : in `a.out`_start   /* No debugging info */
0x107d0 : in `a.out`_start   /* No debugging info */
0x10c2c : in `a.out`t.c`main at "t.c":8
0xff36b214 : in `libumem.so.1`malloc.c`process_free   /* No debugging info */
0xff36dfec : in `libumem.so.1`_umem_cache_free   /* No debugging info */
=================================================================

# Don't ask me why _start shows up twice in libumem stack capture.
# It's probably a stray tail-call optimization someplace.

# If you want to see the recent history of allocations/frees, do this:

(dbx) u log
       Log Rec Addr          Block Addr   Thrd         Timestamp
       ------------          ----------   ----         ---------
            0x32000             0x5bfe0    1     0xbda1d488b15c8
            0x32064             0x5bfc0    1     0xbda1d488b6fa0
            0x320c8             0x5bfa0    1     0xbda1d488b8260
            0x3212c             0x5bfa0    1     0xbda1d488ba010