From 8ab8483c8f876480d5979e4b54e2e6f33cd9b7a7 Mon Sep 17 00:00:00 2001 From: Andreas Dilger Date: Fri, 9 Dec 2022 21:59:56 -0700 Subject: [PATCH] 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 Change-Id: Ieefd5f5336252edcd3916a409c6c046a57b07dc4 Reviewed-on: https://review.whamcloud.com/c/fs/lustre-release/+/49357 Tested-by: jenkins Tested-by: Maloo Reviewed-by: Emoly Liu Reviewed-by: Alex Deiter Reviewed-by: Oleg Drokin --- lustre/tests/leak_finder.pl | 161 ++++++++++++++++++++++++++++---------------- 1 file changed, 104 insertions(+), 57 deletions(-) diff --git a/lustre/tests/leak_finder.pl b/lustre/tests/leak_finder.pl index d2db8a5..71ae03c 100644 --- 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 [--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 = ) { - 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 = ) { +# 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 = ) { $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 = ) { $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 = ) { 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 = ) { $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"; -- 1.8.3.1