#!/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->{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->{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->{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->{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 { $line = shift; # print "$_\n"; if ($line =~ /(\d+)\:(\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 = /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($_); # 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 ($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->{LNET} || $linesubsys == $subsys->{LND})); if($rpctrace && !$entering_rpc) {entering_rpc($_);} if($rpctrace && !$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]);