X-Git-Url: https://git.whamcloud.com/?a=blobdiff_plain;f=lustre%2Futils%2Fllanalyze;h=bb78a6b3956649bba227c92033f7a53848205fda;hb=3b0094779b58c162e5dc553f6d7cdff1910d0c3b;hp=e3e21d6336308bd3cb10742207245b2ead0ebabe;hpb=ab6f9e2f8e8ae2b5f7db2e27784f3ed2fd23855c;p=fs%2Flustre-release.git diff --git a/lustre/utils/llanalyze b/lustre/utils/llanalyze index e3e21d6..bb78a6b 100644 --- a/lustre/utils/llanalyze +++ b/lustre/utils/llanalyze @@ -1,65 +1,123 @@ #!/usr/bin/perl use Getopt::Long; +use Term::ANSIColor; + GetOptions("pid=i" => \$pid, "trace!" => \$trace, + "silent!" => \$silent, + "rpctrace!" => \$rpctrace, "nodlm!" => \$nodlm, - "nonet!" => \$nonet); - -print "pid: $pid, nodlm $nodlm nonet $nonet trace $trace\n"; - -$subsys->{UNDEFINED} = 0; -$subsys->{MDC} = 1; -$subsys->{MDS} = 2; -$subsys->{OSC} = 3; -$subsys->{OST} = 4; -$subsys->{CLASS} = 5; -$subsys->{OBDFS} = 6; -$subsys->{LLITE} = 7; -$subsys->{RPC} = 8; -$subsys->{EXT2OBD} = 9; -$subsys->{PORTALS} = 10; -$subsys->{SOCKNAL} = 11; -$subsys->{QSWNAL} = 12; -$subsys->{PINGER} = 13; -$subsys->{FILTER} = 14; -$subsys->{TRACE} = 15; # obdtrace, not to be confused with D_TRACE */ -$subsys->{ECHO} = 16; -$subsys->{LDLM} = 17; -$subsys->{LOV} = 18; -$subsys->{GMNAL} = 19; -$subsys->{PTLROUTER} = 20; + "dlm_ns=s" => \$dlm_ns, + "noclass!" => \$noclass, + "nonet!" => \$nonet, + "extract_start=s" => \$extract_start, + "extract_end=s" => \$extract_end); + + + +$subsys->{UNDEFINED} = 1 << 0; +$subsys->{MDC} = 1 << 1; +$subsys->{MDS} = 1 << 2; +$subsys->{OSC} = 1 << 3; +$subsys->{OST} = 1 << 4; +$subsys->{CLASS} = 1 << 5; +$subsys->{LOG} = 1 << 6; +$subsys->{LLITE} = 1 << 7; +$subsys->{RPC} = 1 << 8; +$subsys->{MGMT} = 1 << 9; +$subsys->{LNET} = 1 << 10; +$subsys->{LND} = 1 << 11; +$subsys->{PINGER} = 1 << 12; +$subsys->{FILTER} = 1 << 13; +# /* 1<< 14 unused */ +$subsys->{ECHO} = 1 << 15; +$subsys->{LDLM} = 1 << 16; +$subsys->{LOV} = 1 << 17; +$subsys->{LQUOTA} = 1 << 18; +$subsys->{OSD} = 1 << 19; +$subsys->{LFSCK} = 1 << 20; +# /* 1<< 21 unused */ +# /* 1<< 22 unused */ +$subsys->{LMV} = 1 << 23; #/* b_new_cmd */ +# /* 1<< 24 unused */ +$subsys->{SEC} = 1 << 25; #/* upcall cache */ +$subsys->{GSS} = 1 << 26; #/* b_new_cmd */ +# /* 1<< 27 unused */ +$subsys->{MGC} = 1 << 28; +$usbsys->{MGS} = 1 << 29; +$subsys->{FID} = 1 << 30; #/* b_new_cmd */ +$subsys->{FLD} = 1 << 31; #/* b_new_cmd */ $masks->{TRACE} = 1 << 0; # /* ENTRY/EXIT markers */ $masks->{INODE} = 1 << 1; # $masks->{SUPER} = 1 << 2; # -$masks->{EXT2} = 1 << 3; # /* anything from ext2_debug */ +$masks->{TTY} = 1 << 3; # /* notification printed to TTY */ $masks->{MALLOC} = 1 << 4; # /* print malloc, free information */ $masks->{CACHE} = 1 << 5; # /* cache-related items */ $masks->{INFO} = 1 << 6; # /* general information */ $masks->{IOCTL} = 1 << 7; # /* ioctl related information */ -$masks->{BLOCKS} = 1 << 8; # /* ext2 block allocation */ +$masks->{NETERROR} = 1 << 8; # /* network errors */ $masks->{NET} = 1 << 9; # /* network communications */ $masks->{WARNING} = 1 << 10; # $masks->{BUFFS} = 1 << 11; # $masks->{OTHER} = 1 << 12; # $masks->{DENTRY} = 1 << 13; # -$masks->{PORTALS} = 1 << 14; # /* ENTRY/EXIT markers */ +$masks->{NETTRACE} = 1 << 14; # /* ENTRY/EXIT markers */ $masks->{PAGE} = 1 << 15; # /* bulk page handling */ $masks->{DLMTRACE} = 1 << 16; # $masks->{ERROR} = 1 << 17; # /* CERROR} = ...) == CDEBUG} = D_ERROR, ...) */ $masks->{EMERG} = 1 << 18; # /* CEMERG} = ...) == CDEBUG} = D_EMERG, ...) */ $masks->{HA} = 1 << 19; # /* recovery and failover */ - - +$masks->{RPCTRACE} = 1 << 20; # /* recovery and failover */ +$masks->{VFSTRACE} = 1 << 21; +$masks->{READA} = 1 << 22; #/* read-ahead */ +$masks->{MMAP} = 1 << 23; +$masks->{CONFIG} = 1 << 24; +$masks->{CONSOLE} = 1 << 25; +$masks->{QUOTA} = 1 << 26; +$masks->{SEC} = 1 << 27; +$masks->{LFSCK} = 1 << 28; +$masks->{HSM} = 1 << 29; sub extractpid { - $_ = shift; + $line = shift; +# print "$_\n"; + if ($line =~ /(\d+)\:(\d+)\:(\d+\.\d+)\:(\d+\.\d+)\:(\d+)\:(\d+)\:.*/) { + return $6; + } +} + +sub extracthostpid +{ + $line = shift; # print "$_\n"; - /l. [0-9]* (.*)\):/; - return $1; + if ($line =~ /(\d+)\:(\d+)\:(\d+\.\d+)\:(\d+)\:(\d+)\:(\d+)\:(\d+)\:.*/) { + return $7; + } +} + +sub entering_rpc +{ + $_ = shift; + $entering_rpc = /Handling RPC/; + if($entering_rpc) { + $oldpid=$pid; + $pid = extractpid($_); + $leaving_rpc = 0; + } +} + +sub leaving_rpc +{ + $_ = shift; + $leaving_rpc = /Handled RPC/; + if($leaving_rpc) { + $pid = $oldpid; + $entering_rpc = 0; + } } sub entering @@ -86,8 +144,167 @@ sub getmask return hex($mask); } -while () { +sub setcolor +{ + my $linemask = shift; + my $line = shift; + if ($linemask == $masks->{TRACE}) { + if(leaving($line)){ + print color("yellow on_black"); + } else { + print color("green on_black"); + } + } + if ($linemask == $masks->{DLMTRACE}) { + print color("magenta on_black"); + } + if ($linemask == $masks->{DLM}) { + print color("magenta on_black"); + } + if ($linemask == $masks->{DENTRY}) { + print color("red on_black"); + } +} + +sub study_lock +{ + $_ = shift; + my $rc; + + $rc = /client-side enqueue returned a blocked.* ns: (.*) lock: (.*) lrc: (.*) mode/; + if ($rc) { + $completion_callbacks{$1}->{$2} = $3; +# print color("white"); +# print "---CP CB START: $1 $2 $3\n"; +# print color("reset"); + } + $rc = /client-side enqueue:.* ns: (.*) lock: (.*) lrc: (.*) mode/; + if ($rc) { +# print color("white"); +# print "---CP CB END: $1 $2 $3 deleting $completion_callbacks{$1}->{$2}\n"; +# print color("reset"); + delete $completion_callbacks{$1}->{$2}; + } + + $rc = /client blocking AST callback handler ns: (.*) lock: (.*) lrc: (.*) mode/; + if ($rc) { + $blocking_callbacks{$1}->{$2} = $3; +# print color("white"); +# print "---BL CB START: $1 $2\n"; +# print color("reset"); + } + $rc = /client blocking callback handler END ns: (.*) lock: (.*) lrc: (.*) mode/; + if ($rc) { +# print color("white"); +# print "---BL CB END: $1 $2 $3 deleting $blocking_callbacks{$1}->{$2}\n"; +# print color("reset"); + delete $blocking_callbacks{$1}->{$2}; + } + + $rc = /ldlm_lock_addref.*ns: (.*) lock: (.*) lrc: (.*) mode/; +# print color("white"); +# print "------>addref ns: $1 lock: $2 lrc: $3\n" if ($rc); +# print color("reset"); + $locks{$1}->{$2} = {$3} if ($rc); + $rc = /ldlm_lock_decref.*ns: (.*) lock: (.*) lrc: (.*) mode/; +# print color("white"); +# print "------>decref ns: $1 lock: $2 lrc: $3\n" if ($rc); +# print color("reset"); + $locks{$1}->{$2} = {$3} if ($rc); +} + +sub hanging_locks +{ + my $found; + my $ns; + + foreach (keys %completion_callbacks) { + $ns = $_; + $found = 0; + foreach (keys %{$completion_callbacks{$ns}}) { + if (!$found) { + print "Unfinished completions in ns $ns: \n"; + $found =1; + } + print " lock: $_ lrc: $completion_callbacks{$ns}->{$_}\n"; + } + } + foreach (keys %blocking_callbacks) { + $ns = $_; + $found = 0; + foreach (keys %{$blocking_callbacks{$ns}}) { + if (!$found) { + print "Unfinished blocking in ns $ns: \n"; + $found =1; + } + printf(" lock: $_ lrc: %s\n", $blocking_callbacks{$ns}->{$_}); + } + } + +} + +sub study_intent +{ + $_ = shift; + my $rc; + + $rc = /D_IT UP dentry (.*) fsdata/; + delete $it{$1} if ($rc); + $rc = /D_IT DOWN dentry (.*) fsdata/; + $it{$1} = "yes" if ($rc); +} + +sub unmatched_intents { + my $found; + foreach (keys %it) { + if (!$found) { + print "Unmatched intents: \n"; + $found =1; + } + print " $_\n"; + } +} + +sub usage +{ + print "Usage : llanalyze LOGFILE\n"; + exit; +} + +if ($ARGV[0]) { + if(!open(LOG, "<$ARGV[0]")){ + print "Cannot open $ARGV[0]\n"; + exit; + } +} else { + usage(); +} +$width = 0; +if ($ARGV[1]) { + $width = $ARGV[1]; +} + +print "nodlm $nodlm, nonet $nonet, trace $trace\n"; +print "pid: $pid, dlm_ns: $dlm_ns\n"; +print "rpctrace: $rpctrace\n"; +print "extract_start: $extract_start\n"; +print "extract_end: $extract_end\n"; +print "width: $width\n"; +while () { + if ($extract_start && $extract_start ne "LLANAYZE_FOUND") { + next if (index($_, $extract_start, 0) == -1); + $extract_start = "LLANAYZE_FOUND"; + } + + if ($extract_end) { + next if ($extract_end eq "LLANAYZE_FOUND"); + if (index($_, $extract_end, 0) != -1) { + $extract_end = "LLANAYZE_FOUND"; + } + } + $linepid = extractpid($_); + $linehpid = extracthostpid($_); $linemask = getmask($_); $linesubsys = getsubsys($_); @@ -97,26 +314,50 @@ while () { chop $prefix->{$linepid}; chop $prefix->{$linepid}; } - if ( !$pid || $linepid == $pid) { + + if ($linemask == $masks->{DENTRY}) { + study_intent($_); + } + if ($linemask == $masks->{DLMTRACE}) { + study_lock($_); + } + + if ( !$pid || $linepid == $pid || $linehpid == $pid) { + next if ($rpctrace && !$entering_rpc && $linemask != $masks->{RPCTRACE}); next if ($trace && $linemask != $masks->{TRACE}); next if ($nodlm && ( $linesubsys == $subsys->{LDLM})); + next if ($dlm_ns && + ( $linesubsys != $subsys->{LDLM})); + next if (($found_dlm_ns = index( $_, $dlm_ns, 0)) == -1); + next if ($noclass && + ( $linesubsys == $subsys->{CLASS})); next if ($nonet && ( $linesubsys == $subsys->{RPC} || $linesubsys == $subsys->{NET} || - $linesubsys == $subsys->{PORTALS} || - $linesubsys == $subsys->{SOCKNAL} || - $linesubsys == $subsys->{QSWNAL} || - $linesubsys == $subsys->{GMNAL})); + $linesubsys == $subsys->{LNET} || + $linesubsys == $subsys->{LND})); + if($rpctrace && !$entering_rpc) {entering_rpc($_);} + if($rpctrace && !$leaving_rpc) {leaving_rpc($_);} # printf "sub/mask: %s - %s\n", getsubsys($_), getmask($_); - - printf "%s%s", $prefix->{$linepid}, $_; - last if $count++ > 100; + if (!$silent) { + setcolor($linemask, $_); + my $string = $prefix->{$linepid}.$_; + if($width){ + $string = substr($string, 0, $width)."\n"; + } + printf("%s", $string); + print color("reset"); + } + # last if $count++ > 100; } if (entering($_)) { $prefix->{$linepid} .= ' '; } } + +unmatched_intents(); +hanging_locks(); # printf "argv %s pid %d\n", $ARGV[0], extractpid($ARGV[0]);