1 Reply Latest reply on Dec 3, 2013 7:56 AM by user8840798

    umem: umalog shows free calls on memory not previously alloced?!


      We have a java webapp that has a problem with a native memory leak (not a java heap leak).  At some point the process balloons to almost 4GB in size and we experience issues creating new threads. I was hoping to use umem to help pinpoint the culprit.  We run the jvm with umem enabled and execute gcore to produce a core file.  I then issue umem dcmds in mdb to gather information. 


      My current plan is to capture and analyze umalog output.  I am using a perl script to process the output of "umalog -e" in reverse order (in time-sequence order in other words).  By keeping a running heap size total (ie adding the buffer sizes of each allocation/ subtracting for free calls) over time I was hoping to detect at what point in time the process ballooned in size, and hopefully correlate that with events from the access log and/or application logs.


      I first am testing with a trivial java application that simply sleeps for a short time.


      public class Sleepy {

              public static void main(String[] args) {

                      try { Thread.sleep(30000); } catch(java.lang.InterruptedException e) {}




      What surprises me is a number of calls to umem_cache_free with addresses that had not previously been allocated by umem_cache_alloc.  (See the comment in the perl script below: "WHY DOES THIS HAPPEN!?") Why would this happen I wonder?  Doesn't each free need be passed a buffer that was earlier acquired via alloc? At initial startup, the heap experiences more free calls then allocs.  This leads my running total of heap size to go negative for a while.  I am guessing there is some flaw in my approach or understanding of umem or the umalog output, since this is clearly impossible.  I'm assuming that all memory transactions are captured in the log.  I'm assuming that the allocation size is the name of the memory buffer (e.g. umem_alloc_40 was an allocation of 40 bytes.  Hmm that last one sounds suspect but I do not need to be exact to the byte I think; just need to see where allocations go nutty.


      I'll try pasting my perl script below.  Any ideas or tips?  Thanks!


      #!/usr/bin/env perl


      use POSIX;


      use strict;


      my $minheap = 0;

      my $maxheap = 0;

      my $heapsize = 0;


      my $maxtimestamp;

      my $maxXactionIndex;

      my $maxLine;


      my $line = 0;

      my $count = 0;

      my $alloccount = 0;

      my $freecount = 0;

      my $totalfree = 0;

      my $totalalloc = 0;


      my %allocs = {};

      my %frees = {};


      my $timestamp;


      my $prevline;


      my $filename = $ARGV[0];


      my $count = countRecords($filename);


      open(LOG, "<$filename") or die "Failed to open file $filename!";


      my $PERCENT_TO_REPORT = 0.05;


      my $reportBoundary = ceil($count * $PERCENT_TO_REPORT);

      #my $reportBoundary = 1;


      print "\nUmem log file name (reversed): $filename\n";

      print "Date: " . (strftime "%F %T", localtime(time)) . "\n\n";

      print(sprintf("%10s %10s %13s   %10s   %s\n", "index", "line", "xaction index", "heap size", "timestamp"));

      print(sprintf("%10s %10s %13s   %10s   %s\n", "----------", "----------", "-------------", "----------", "------------"));


      my $xactionIndex = 0;

      my $reportIndex = 0;

      while(<LOG>) {



              if( /^T(-\d+\.\d+).*addr=(\w+).*umem_alloc_(\d+)/) {


                      $timestamp = $1;

                      my $addr = $2;

                      my $size = $3;

                      $prevline =~ /umem_cache_(\w+)/;


                      my $op = $1;


                      if( $op eq "alloc" ) {


                              $heapsize += $size;

                              $totalalloc += $size;

                              $allocs{$addr} = $size;

                      } else {


                              $heapsize -= $size;

                              $totalfree += $size;


                              if( !defined($allocs{$addr}) ) {

                                      print "*** No alloc of addr $addr was made previously! line $line; $op $size\n";  // WHY DOES THIS HAPPEN!?




                      if( $heapsize > $maxheap ) {

                              $maxheap = $heapsize;

                              $maxtimestamp = $timestamp;

                              $maxXactionIndex = $xactionIndex;

                              $maxLine = $line;


                      if( $heapsize < $minheap ) {

                              $minheap = $heapsize;



                      if( ($xactionIndex % $reportBoundary) == 0 or $xactionIndex == $count ) {


                              report($reportIndex, $line, $xactionIndex, $heapsize, $timestamp);


              } else {

                      $prevline = $_;




      close LOG;


      print "\n\nMax heap size was " . fmt($maxheap) . " at line $maxLine, xaction index $maxXactionIndex, at timestamp $maxtimestamp\n\n";

      print "There were " . fmt($count) . " memory operations; $alloccount allocs and $freecount frees\n";

      print "Total memory allocated: " . fmt($totalalloc) . + "\n";

      print "Total memory freed    : " . fmt($totalfree) . + "\n";

      print "Min heap size was $minheap\n";



      exit 0;


      sub countRecords {


              my $filename = $_[0];


              my $count = 0;


              open( LOGFILE, "<$filename" ) or die "Failed to open input file $filename!";

              while(<LOGFILE>) {

                      if(/^T/) { $count++ }


              close LOGFILE;


              return $count;



      sub report {

              my $reportIndex = $_[0];

              my $line = $_[1];

              my $xactionIndex = $_[2];

              my $heapsize = $_[3];

              my $timestamp = $_[4];


              $heapsize =~ s/(\d)(?=(\d{3})+(\D|$))/$1\,/g;

              print(sprintf("%10d %10d %13d   %10s   %s\n", $reportIndex, $line, $xactionIndex, $heapsize, $timestamp));



      sub fmt {

              my $number = $_[0];

              $number =~ s/(\d)(?=(\d{3})+(\D|$))/$1\,/g;