lustre/utils/llanalyze

   1 #!/usr/bin/perl
   2
   3 use Getopt::Long;
   4 use Term::ANSIColor;
   5
   6 GetOptions("pid=i" => \$pid,
   7            "trace!" => \$trace,
   8            "silent!" => \$silent,
   9            "rpctrace!" => \$rpctrace,
  10            "nodlm!" => \$nodlm,
  11            "dlm_ns=s" => \$dlm_ns,
  12            "noclass!" => \$noclass,
  13            "nonet!" => \$nonet,
  14            "extract_start=s" => \$extract_start,
  15            "extract_end=s" => \$extract_end);
  16
  17
  18
  19 $subsys->{UNDEFINED} = 1 << 0;
  20 $subsys->{MDC} = 1 << 1;
  21 $subsys->{MDS} = 1 << 2;
  22 $subsys->{OSC} = 1 << 3;
  23 $subsys->{OST} = 1 << 4;
  24 $subsys->{CLASS} = 1 << 5;
  25 $subsys->{LOG} = 1 << 6;
  26 $subsys->{LLITE} = 1 << 7;
  27 $subsys->{RPC} = 1 << 8;
  28 $subsys->{MGMT} = 1 << 9;
  29 $subsys->{PORTALS} = 1 << 10;
  30 $subsys->{SOCKNAL} = 1 << 11;
  31 $subsys->{QSWNAL} = 1 << 12;
  32 $subsys->{PINGER} = 1 << 13;
  33 $subsys->{FILTER} = 1 << 14;
  34 $subsys->{PTLBD} = 1 << 15;
  35 $subsys->{ECHO} = 1 << 16;
  36 $subsys->{LDLM} = 1 << 17;
  37 $subsys->{LOV} = 1 << 18;
  38 $subsys->{GMNAL} = 1 << 19;
  39 $subsys->{PTLROUTER} = 1 << 20;
  40 $subsys->{COBD} = 1 << 21;
  41 $subsys->{OPENIBNAL} = 1 << 22;
  42
  43
  44 $masks->{TRACE} = 1 << 0; # /* ENTRY/EXIT markers */
  45 $masks->{INODE} = 1 << 1; #
  46 $masks->{SUPER} = 1 << 2; #
  47 $masks->{EXT2} = 1 << 3; # /* anything from ext2_debug */
  48 $masks->{MALLOC} = 1 << 4; # /* print malloc, free information */
  49 $masks->{CACHE} = 1 << 5; # /* cache-related items */
  50 $masks->{INFO} = 1 << 6; # /* general information */
  51 $masks->{IOCTL} = 1 << 7; # /* ioctl related information */
  52 $masks->{BLOCKS} = 1 << 8; # /* ext2 block allocation */
  53 $masks->{NET} = 1 << 9; # /* network communications */
  54 $masks->{WARNING} = 1 << 10; #
  55 $masks->{BUFFS} = 1 << 11; #
  56 $masks->{OTHER} = 1 << 12; #
  57 $masks->{DENTRY} = 1 << 13; #
  58 $masks->{PORTALS} = 1 << 14; # /* ENTRY/EXIT markers */
  59 $masks->{PAGE} = 1 << 15; # /* bulk page handling */
  60 $masks->{DLMTRACE} = 1 << 16; #
  61 $masks->{ERROR} = 1 << 17; # /* CERROR} = ...) == CDEBUG} = D_ERROR, ...) */
  62 $masks->{EMERG} = 1 << 18; # /* CEMERG} = ...) == CDEBUG} = D_EMERG, ...) */
  63 $masks->{HA} = 1 << 19; # /* recovery and failover */
  64 $masks->{RPCTRACE} = 1 << 19; # /* recovery and failover */
  65
  66 sub extractpid
  67 {
  68     $line = shift;
  69 #    print "$_\n";
  70     if ($line =~ /(\d+)\:(\d+)\:(\d+)\:(\d+\.\d+)\:(\d+)\:(\d+)\:.*/) {
  71         return $6;
  72     }
  73 }
  74
  75 sub extracthostpid
  76 {
  77     $line = shift;
  78 #    print "$_\n";
  79     if ($line =~ /(\d+)\:(\d+)\:(\d+)\:(\d+\.\d+)\:(\d+)\:(\d+)\:(\d+)\:.*/) {
  80         return $7;
  81     }
  82 }
  83
  84 sub entering_rpc
  85 {
  86         $_ = shift;
  87         $entering_rpc  = /Handling RPC/;
  88         if($entering_rpc) {
  89                 $oldpid=$pid;
  90                 $pid = extractpid($_);
  91                 $leaving_rpc = 0;
  92         }
  93 }
  94
  95 sub leaving_rpc
  96 {
  97         $_ = shift;
  98         $leaving_rpc  = /Handled RPC/;
  99         if($leaving_rpc) {
 100                 $pid = $oldpid;
 101                 $entering_rpc = 0;
 102         }
 103 }
 104
 105 sub entering
 106 {
 107     $_ = shift;
 108     $entering = /Process entered/;
 109 }
 110
 111 sub leaving
 112 {
 113     $_ = shift;
 114     $entering = /Process leaving/;
 115 }
 116
 117 sub getsubsys
 118 {
 119     my ($subsys, $mask) = split ":";
 120     return hex($subsys);
 121 }
 122
 123 sub getmask
 124 {
 125     my ($subsys, $mask) = split ":";
 126     return hex($mask);
 127 }
 128
 129 sub setcolor
 130 {
 131     my $linemask = shift;
 132     my $line = shift;
 133     if ($linemask == $masks->{TRACE}) {
 134         if(leaving($line)){
 135            print color("yellow on_black");
 136         } else {
 137            print color("green on_black");
 138         }
 139     }
 140     if ($linemask == $masks->{DLMTRACE}) {
 141         print color("magenta on_black");
 142     }
 143     if ($linemask == $masks->{DLM}) {
 144         print color("magenta on_black");
 145     }
 146     if ($linemask == $masks->{DENTRY}) {
 147         print color("red on_black");
 148     }
 149 }
 150
 151 sub study_lock
 152 {
 153     $_ = shift;
 154     my $rc;
 155
 156     $rc = /completion callback handler START ns: (.*) lock: (.*) lrc: (.*) mode/;
 157     if ($rc) {
 158         $completion_callbacks{$1}->{$2} = $3;
 159 #         print color("white");
 160 #         print "---CP CB START: $1 $2 $3\n";
 161 #         print color("reset");
 162     }
 163     $rc = /callback handler finished.* ns: (.*) lock: (.*) lrc: (.*) mode/;
 164     if ($rc) {
 165 #         print color("white");
 166 #         print "---CP CB END: $1 $2 $3 deleting $completion_callbacks{$1}->{$2}\n";
 167 #         print color("reset");
 168         delete $completion_callbacks{$1}->{$2};
 169     }
 170
 171     if ($rc) {
 172         $rc = /client blocking AST callback handler START ns: (.*) lock: (.*) lrc: (.*) mode/;
 173         $blocking_callbacks{$1}->{$2} = $3;
 174 #         print color("white");
 175 #         print "---BL CB START: $1 $2\n";
 176 #         print color("reset");
 177     }
 178     $rc = /client blocking callback handler END ns: (.*) lock: (.*) lrc: (.*) mode/;
 179     if ($rc) {
 180 #         print color("white");
 181 #         print "---BL CB END: $1 $2 $3 deleting $blocking_callbacks{$1}->{$2}\n";
 182 #         print color("reset");
 183         delete $blocking_callbacks{$1}->{$2};
 184     }
 185
 186     $rc = /ldlm_lock_addref.*ns: (.*) lock: (.*) lrc: (.*) mode/;
 187 #     print color("white");
 188 #     print "------>addref ns: $1 lock: $2 lrc: $3\n" if ($rc);
 189 #     print color("reset");
 190     $locks{$1}->{$2} = {$3} if ($rc);
 191     $rc = /ldlm_lock_decref.*ns: (.*) lock: (.*) lrc: (.*) mode/;
 192 #     print color("white");
 193 #     print "------>decref ns: $1 lock: $2 lrc: $3\n" if ($rc);
 194 #     print color("reset");
 195     $locks{$1}->{$2} = {$3} if ($rc);
 196 }
 197
 198 sub hanging_locks
 199 {
 200     my $found;
 201     my $ns;
 202
 203     foreach (keys %completion_callbacks) {
 204         $ns = $_;
 205         $found = 0;
 206         foreach (keys %{$completion_callbacks{$ns}}) {
 207             if (!$found) {
 208                 print "Unfinished completions in ns $ns: \n";
 209                 $found =1;
 210             }
 211             print "  lock: $_ lrc: $completion_callbacks{$ns}->{$_}\n";
 212         }
 213     }
 214     foreach (keys %blocking_callbacks) {
 215         $ns = $_;
 216         $found = 0;
 217         foreach (keys %{$blocking_callbacks{$ns}}) {
 218             if (!$found) {
 219                 print "Unfinished blocking in ns $ns: \n";
 220                 $found =1;
 221             }
 222             printf("  lock: $_ lrc: %s\n", $blocking_callbacks{$ns}->{$_});
 223         }
 224     }
 225
 226 }
 227
 228 sub study_intent
 229 {
 230     $_ = shift;
 231     my $rc;
 232
 233     $rc = /D_IT UP dentry (.*) fsdata/;
 234     delete $it{$1} if ($rc);
 235     $rc = /D_IT DOWN dentry (.*) fsdata/;
 236     $it{$1} = "yes"  if ($rc);
 237 }
 238
 239 sub unmatched_intents {
 240     my $found;
 241     foreach (keys %it) {
 242         if (!$found) {
 243             print "Unmatched intents: \n";
 244             $found =1;
 245         }
 246         print "  $_\n";
 247     }
 248 }
 249
 250 sub usage
 251 {
 252    print "Usage : llanalyze LOGFILE\n";
 253    exit;
 254 }
 255
 256 if ($ARGV[0]) {
 257     if(!open(LOG, "<$ARGV[0]")){
 258       print "Cannot open $ARGV[0]\n";
 259       exit;
 260     }
 261 } else {
 262     usage();
 263 }
 264 $width = 0;
 265 if ($ARGV[1]) {
 266    $width = $ARGV[1];
 267 }
 268
 269 print "nodlm $nodlm, nonet $nonet, trace $trace\n";
 270 print "pid: $pid, dlm_ns: $dlm_ns\n";
 271 print "extract_start: $extract_start\n";
 272 print "extract_end:   $extract_end\n";
 273 while (<LOG>) {
 274     if ($extract_start && $extract_start ne "LLANAYZE_FOUND") {
 275         next if (index($_, $extract_start, 0) == -1);
 276         $extract_start = "LLANAYZE_FOUND";
 277     }
 278
 279     if ($extract_end) {
 280         next if ($extract_end eq "LLANAYZE_FOUND");
 281         if (index($_, $extract_end, 0) != -1) {
 282              $extract_end = "LLANAYZE_FOUND";
 283         }
 284     }
 285
 286     $linepid = extractpid($_);
 287     $linehpid = extracthostpid($_);
 288     $linemask = getmask($_);
 289     $linesubsys = getsubsys($_);
 290
 291 #    printf "---> mask %x subsys %x\n", $linemask, $linesubsys;
 292
 293     if (leaving($_)) {
 294         chop $prefix->{$linepid};
 295         chop $prefix->{$linepid};
 296     }
 297
 298     if ($linemask == $masks->{DENTRY}) {
 299         study_intent($_);
 300     }
 301     if ($linemask == $masks->{DLMTRACE}) {
 302         study_lock($_);
 303     }
 304
 305     if ( !$pid || $linepid == $pid || $linehpid == $pid) {
 306         next if (!$entering_rpc && $rpctrace && $linemask != $masks->{RPCTRACE});
 307         next if ($trace && $linemask != $masks->{TRACE});
 308         next if ($nodlm &&
 309                  (  $linesubsys == $subsys->{LDLM}));
 310         next if ($dlm_ns &&
 311                  (  $linesubsys != $subsys->{LDLM}));
 312         next if (($found_dlm_ns = index( $_, $dlm_ns, 0)) == -1);
 313         next if ($noclass &&
 314                  (  $linesubsys == $subsys->{CLASS}));
 315         next if ($nonet &&
 316                  (  $linesubsys == $subsys->{RPC} ||
 317                     $linesubsys == $subsys->{NET} ||
 318                     $linesubsys == $subsys->{PORTALS} ||
 319                     $linesubsys == $subsys->{SOCKNAL} ||
 320                     $linesubsys == $subsys->{QSWNAL} ||
 321                     $linesubsys == $subsys->{OPENIBNAL} ||
 322                     $linesubsys == $subsys->{GMNAL}));
 323         if(!$entering_rpc) {entering_rpc($_);}
 324         if(!$leaving_rpc) {leaving_rpc($_);}
 325
 326 #        printf "sub/mask: %s - %s\n", getsubsys($_), getmask($_);
 327         if (!$silent) {
 328             setcolor($linemask, $_);
 329             my $string = $prefix->{$linepid}.$_;
 330             if($width){
 331                $string = substr($string, 0, $width)."\n";
 332             }
 333             printf("%s", $string);
 334             print color("reset");
 335         }
 336             #        last if $count++ > 100;
 337     }
 338     if (entering($_)) {
 339         $prefix->{$linepid} .= '  ';
 340     }
 341 }
 342
 343
 344 unmatched_intents();
 345 hanging_locks();
 346 # printf "argv %s pid %d\n", $ARGV[0], extractpid($ARGV[0]);