LU-14736 tests: improve leak-finder compatibility

Add regexps for leak-finder.pl to still be able to parse older
debug logs for ease of use.

Improve --summary mode so that it only prints the summary, instead of
every line that is parsed.  Add --debug to print every line if needed.

Track free-without-alloc calls so that --summary can be used on debug
logs captured during cleanup to aggregate frees that were allocated
before the debug log was started.  This will show "leaks" as negative
allocations for each callsite (i.e. more memory freed than allocated).

Print total allocated and freed in summary line.

Fixes: 5b998d803f ("LU-14736 utils: update leak-finder.pl for new format")
Signed-off-by: Andreas Dilger <adilger@whamcloud.com>
Change-Id: Ieefd5f5336252edcd3916a409c6c046a57b07dc4
Reviewed-on: https://review.whamcloud.com/c/fs/lustre-release/+/49357
Tested-by: jenkins <devops@whamcloud.com>
Tested-by: Maloo <maloo@whamcloud.com>
Reviewed-by: Emoly Liu <emoly@whamcloud.com>
Reviewed-by: Alex Deiter <alex.deiter@gmail.com>
Reviewed-by: Oleg Drokin <green@whamcloud.com>

diff --git a/lustre/tests/leak_finder.pl b/lustre/tests/leak_finder.pl
index d2db8a5..71ae03c 100644 (file)
--- a/lustre/tests/leak_finder.pl
+++ b/lustre/tests/leak_finder.pl
@@ -8,8 +8,13 @@ STDERR->autoflush(1);
 my ($line, $memory);
 my $debug_line = 0;
 
-my $total = 0;
+my $alloced = 0;
+my $leaked = 0;
+my $freed = 0;
 my $max = 0;
+my $debug = 0;
+my $summary = 0;
+my $by_func = 0;
 
 my @parsed;
 my %cpu;
@@ -18,49 +23,60 @@ my $start_time = 0;
 if (!defined($ARGV[0])) {
     print "No log file specified\n";
     print "Usage: leak_finder.pl <debug_file> [--option]\n";
-    print "    --by_func show leak logs by function name in ascending order.\n";
-    print "    --summary implies --by_func, print a summary report by \n";
+    print "    --by-func show leak logs by function name in ascending order.\n";
+    print "    --debug   print more verbose debugging information.\n";
+    print "    --summary implies --by-func, print a summary report by \n";
     print "              the number of total leak bytes of each function \n";
     print "              in ascending order in YAML format.\n";
     exit
 }
 
-open(INFILE, $ARGV[0]);
-while ($line = <INFILE>) {
-    if ($line =~ m/^(.*)\((.*):(\d+):(.*)\(\)\)/) {
-        @parsed = split(":", $1);
-        if (substr ($parsed[2], -1, 1) eq "F") {
-            chop $parsed[2];
-            $cpu{$parsed[2]} = 0;
-        } else {
-            if (!defined($cpu{$parsed[2]})) {
-                $cpu{$parsed[2]} = $parsed[3];
-            }
-        }
-    }
+if (defined($ARGV[1]) and $ARGV[1] eq "--debug") {
+    $debug = 1;
 }
 
-foreach $time (values %cpu) {
-    if ($start_time < $time) {
-        $start_time = $time;
-    }
+if (defined($ARGV[1]) and $ARGV[1] eq "--summary") {
+    $summary = 1;
+    $by_func = 1;
+}
+
+if (defined($ARGV[1]) and ($ARGV[1] eq "--by-func" || $ARGV[1] eq "--by_func")) {
+    $by_func = 1;
 }
 
-print "Starting analysis since $start_time\n";
+open(INFILE, $ARGV[0]);
+#while ($line = <INFILE>) {
+#    if ($line =~ m/^(.*)\((.*):(\d+):(.*)\(\)\)/) {
+#        @parsed = split(":", $1);
+#        if (substr ($parsed[2], -1, 1) eq "F") {
+#            chop $parsed[2];
+#            $cpu{$parsed[2]} = 0;
+#        } else {
+#            if (!defined($cpu{$parsed[2]})) {
+#                $cpu{$parsed[2]} = $parsed[3];
+#            }
+#        }
+#    }
+#}
+#
+#foreach $time (values %cpu) {
+#    if ($start_time < $time) {
+#        $start_time = $time;
+#    }
+#}
+#
+#print "Starting analysis since $start_time\n";
 
 seek(INFILE, 0, 0);
 while ($line = <INFILE>) {
     $debug_line++;
+
     my ($file, $func, $lno, $name, $size, $addr, $type);
     # message format here needs to match OBD_ALLOC_POST()/OBD_FREE_PRE()
     # mask:subs:cpu:epoch second.usec:?:pid:?:(filename:line:function_name())
     #    alloc-type 'var_name': size at memory_address.
-    if ($line =~ m/^(.*)\((.*):(\d+):(.*)\(\)\) (k[m]?|v[m]?|slab-|)(alloc(ed)?|free[d]?(_rcu)?) '(.*)': (\d+) at ([\da-f]+)/) {
-        @parsed = split(":", $1);
-        if ($parsed[3] <= $start_time) {
-                next;
-        }
-
+    if ($line =~ m/^(.*)\((.*):(\d+):(.*)\(\)\) (k[m]?|v[m]?|slab-|)(alloc(ed)?|free[d]?(_rcu)?) '(.*)': (\d+) at ([\da-f]+)/ ||
+        $line =~ m/^(.*)\((.*):(\d+):(.*)\(\)\) (k[m]?|v[m]?|slab-|)(alloc(ed)?|free[d]?(_rcu)?) '(.*)' of size (\d+) at ([\da-f]+)/) {
         $file = $2;
         $lno  = $3;
         $func = $4;
@@ -68,15 +84,15 @@ while ($line = <INFILE>) {
         $name = $9;
         $size = $10;
         $addr = $11;
-
-       # we can't dump the log after portals has exited, so skip "leaks"
-       # from memory freed in the portals module unloading.
-       if ($func eq 'portals_handle_init') {
-           next;
-       }
-        printf("%8s %6d bytes at %s called %s (%s:%s:%d)\n", $type, $size,
-               $addr, $name, $file, $func, $lno);
-    } elsif ($line =~ m/(alloc(ed)?|free[d]?).*at [0-9a-f]*/) {
+    } elsif ($line =~ m/^(.*)\((.*):(\d+):(.*)\(\)\) (slab-)(alloc(ed)?|free[d]?) '(.*)' at ([\da-f]+)/) {
+        $file = $2;
+        $lno  = $3;
+        $func = $4;
+        $type = $6;
+        $name = $8;
+        $size = 0;
+        $addr = $9;
+    } elsif ($line =~ m/([ -]alloc(ed)? |[ -]free[d]? ).*at [0-9a-f]*/) {
         # alloc/free line that didn't match regexp, notify user of missed line
         print STDERR "Couldn't parse line $debug_line, script needs to be fixed:\n$line";
         next;
@@ -86,11 +102,25 @@ while ($line = <INFILE>) {
         next;
     }
 
+    # we can't dump the log after portals has exited, so skip "leaks"
+    # from memory freed in the portals module unloading.
+    if ($func =~ 'portals_handle_init') {
+        next;
+    }
+
+    if ($debug) {
+        print $line;
+    }
+    if ($summary == 0) {
+        printf("%8s %6d bytes at %s called %s (%s:%s:%d)\n", $type, $size,
+               $addr, $name, $file, $func, $lno);
+    }
+
     if (index($type, 'alloc') >= 0) {
         if (defined($memory->{$addr})) {
-            print STDOUT "*** Two allocs with the same address ($size bytes at $addr, $file:$func:$lno)\n";
-            print STDOUT "    first malloc at $memory->{$addr}->{file}:$memory->{$addr}->{func}:$memory->{$addr}->{lno}, second at $file:$func:$lno\n";
-            next;
+            print STDOUT "*** Two allocs with the same address $addr\n";
+            print STDOUT "    first malloc $memory->{$addr}->{size} bytes at $memory->{$addr}->{file}:$memory->{$addr}->{func}:$memory->{$addr}->{lno}, second $size bytes at $file:$func:$lno\n";
+           $memory->{$addr . "_a"} = $memory->{$addr};
         }
 
         $memory->{$addr}->{name} = $name;
@@ -100,25 +130,42 @@ while ($line = <INFILE>) {
         $memory->{$addr}->{lno} = $lno;
         $memory->{$addr}->{debug_line} = $debug_line;
 
-        $total += $size;
-        if ($total > $max) {
-            $max = $total;
+        $alloced += $size;
+        if ($alloced > $max) {
+            $max = $alloced;
         }
     } else {
         if (!defined($memory->{$addr})) {
-            print STDOUT "*** Free without malloc ($size bytes at $addr, $file:$func:$lno)\n";
+            if ($summary == 0) {
+                print STDOUT "*** Free without alloc ($size bytes at $addr, $file:$func:$lno)\n";
+            }
+           # offset addr to avoid alloc collision, shouldn't be multiple frees
+           $addr = $addr . "_f";
+            $memory->{$addr}->{name} = $name;
+            $memory->{$addr}->{size} = -$size;
+            $memory->{$addr}->{file} = $file;
+            $memory->{$addr}->{func} = $func;
+            $memory->{$addr}->{lno} = $lno;
+            $memory->{$addr}->{debug_line} = $debug_line;
+
+            $freed -= $size;
             next;
         }
         my ($oldname, $oldsize, $oldfile, $oldfunc, $oldlno) = $memory->{$addr};
 
+        if ($size == 0) {
+            $size = $memory->{$addr}->{size};
+        }
         if ($memory->{$addr}->{size} != $size) {
-            print STDOUT "*** Free different size ($memory->{$addr}->{size} alloced, $size freed).\n";
+            print STDOUT "*** Free different size ($memory->{$addr}->{size} alloced, $size freed at $addr).\n";
             print STDOUT "    malloc at $memory->{$addr}->{file}:$memory->{$addr}->{func}:$memory->{$addr}->{lno}, free at $file:$func:$lno\n";
+
+            $freed -= $size;
             next;
         }
 
         delete $memory->{$addr};
-        $total -= $size;
+       $alloced -= $size;
     }
 }
 close(INFILE);
@@ -126,13 +173,11 @@ close(INFILE);
 my $aa;
 my $bb;
 my @sorted = sort {
-    if (defined($ARGV[1])) {
-        if ($ARGV[1] eq "--by_func" or $ARGV[1] eq "--summary") {
-            # Sort leak output by source code position
-            $aa = "$memory->{$a}->{func}:$memory->{$a}->{lno}:$memory->{$a}->{name}:$memory->{$a}->{size}";
-            $bb = "$memory->{$b}->{func}:$memory->{$b}->{lno}:$memory->{$b}->{name}:$memory->{$b}->{size}";
-            $aa cmp $bb;
-        }
+    if ($by_func) {
+        # Sort leak output by source code position
+        $aa = "$memory->{$a}->{func}:$memory->{$a}->{lno}:$memory->{$a}->{name}:$memory->{$a}->{size}";
+        $bb = "$memory->{$b}->{func}:$memory->{$b}->{lno}:$memory->{$b}->{name}:$memory->{$b}->{size}";
+        $aa cmp $bb;
     } else {
         # Sort leak output by allocation time
         $memory->{$a}->{debug_line} <=> $memory->{$b}->{debug_line};
@@ -148,7 +193,7 @@ my $leak_size = 0;
 my $leak_func;
 my $i = 0;
 foreach $key (@sorted) {
-    if (defined($ARGV[1]) and $ARGV[1] eq "--summary") {
+    if ($summary) {
         $aa = "$memory->{$key}->{func}:$memory->{$key}->{lno}:$memory->{$key}->{name}:$memory->{$key}->{size}";
         if ($bb eq $aa) {
             $leak_count++;
@@ -164,20 +209,22 @@ foreach $key (@sorted) {
             $bb = $aa;
         }
         $leak_func = "$memory->{$key}->{func}:$memory->{$key}->{lno}:$memory->{$key}->{name}";
-        $leak_size = $memory->{$key}->{size};
     } else {
         print STDOUT "*** Leak: $memory->{$key}->{size} bytes allocated at $key ($memory->{$key}->{file}:$memory->{$key}->{func}:$memory->{$key}->{lno}:$memory->{$key}->{name}, debug file line $memory->{$key}->{debug_line})\n";
     }
+    
+    $leak_size = $memory->{$key}->{size};
+    $leaked += $leak_size;
 }
 
-if (defined($ARGV[1]) and $ARGV[1] eq "--summary") {
+if ($summary) {
     # print a summary report by total leak bytes in ASC order
     my @sorted_records = sort {
         $a->{total} <=> $b->{total};
     } @records;
     foreach $key (@sorted_records) {
-        printf("- { func: %-58s, alloc_bytes: %-8d, leak_count: %-6d, leak_bytes: %-8d },\n",
+        printf("- { func: \"%-48s\", alloc_bytes: %-6d, leak_count: %-6d, leak_bytes: %-8d }\n",
                $key->{func}, $key->{size}, $key->{count}, $key->{total});
     }
 }
-print STDOUT "maximum used: $max, amount leaked: $total\n";
+print STDOUT "maximum_used: $max, total_alloc: $alloced, freed: $freed, leaked: $leaked\n";