#!/usr/bin/perl use Getopt::Long; use Term::ANSIColor; GetOptions("pid=i" => \$pid, "trace!" => \$trace, "silent!" => \$silent, "rpctrace!" => \$rpctrace, "nodlm!" => \$nodlm, "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->{PORTALS} = 1 << 10; $subsys->{SOCKNAL} = 1 << 11; $subsys->{QSWNAL} = 1 << 12; $subsys->{PINGER} = 1 << 13; $subsys->{FILTER} = 1 << 14; $subsys->{PTLBD} = 1 << 15; $subsys->{ECHO} = 1 << 16; $subsys->{LDLM} = 1 << 17; $subsys->{LOV} = 1 << 18; $subsys->{GMNAL} = 1 << 19; $subsys->{PTLROUTER} = 1 << 20; $subsys->{COBD} = 1 << 21; $subsys->{OPENIBNAL} = 1 << 22; $masks->{TRACE} = 1 << 0; # /* ENTRY/EXIT markers */ $masks->{INODE} = 1 << 1; # $masks->{SUPER} = 1 << 2; # $masks->{EXT2} = 1 << 3; # /* anything from ext2_debug */ $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->{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->{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 << 19; # /* recovery and failover */ sub extractpid { $line = shift; # print "$_\n"; if ($line =~ /(\d+)\:(\d+)\:(\d+)\:(\d+\.\d+)\:(\d+)\:(\d+)\:.*/) { return $6; } } sub extracthostpid { $line = shift; # print "$_\n"; 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 { $_ = shift; $entering = /Process entered/; } sub leaving { $_ = shift; $entering = /Process leaving/; } sub getsubsys { my ($subsys, $mask) = split ":"; return hex($subsys); } sub getmask { my ($subsys, $mask) = split ":"; return hex($mask); } 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 = /completion callback handler START 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 = /callback handler finished.* 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}; } if ($rc) { $rc = /client blocking AST callback handler START ns: (.*) lock: (.*) lrc: (.*) mode/; $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 "extract_start: $extract_start\n"; print "extract_end: $extract_end\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($_); # printf "---> mask %x subsys %x\n", $linemask, $linesubsys; if (leaving($_)) { chop $prefix->{$linepid}; chop $prefix->{$linepid}; } if ($linemask == $masks->{DENTRY}) { study_intent($_); } if ($linemask == $masks->{DLMTRACE}) { study_lock($_); } if ( !$pid || $linepid == $pid || $linehpid == $pid) { next if (!$entering_rpc && $rpctrace && $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->{OPENIBNAL} || $linesubsys == $subsys->{GMNAL})); if(!$entering_rpc) {entering_rpc($_);} if(!$leaving_rpc) {leaving_rpc($_);} # printf "sub/mask: %s - %s\n", getsubsys($_), getmask($_); 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]);