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->{IBNAL} = 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 =~ m/(\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 =~ m/(\d+):(\d+):(\d+):(\d+\.\d+):(\d+):(\d+):(\d+):.*$/) {
  80         return $7;
  81     }
  82 }
  83 sub extractsubsys
  84 {
  85     $line = shift;
  86 #    print "$_\n";
  87     if ($line =~ m/(\d+):(\d+):(\d+):(\d+\.\d+):(\d+):(\d+):(\d+):.*$/) {
  88         return hex($1);
  89     }
  90 }
  91
  92 sub extractmask
  93 {
  94     $line = shift;
  95 #    print "$_\n";
  96     if ($line =~ m/(\d+):(\d+):(\d+):(\d+\.\d+):(\d+):(\d+):(\d+):.*$/) {
  97         return hex($2);
  98     }
  99 }
 100
 101 sub entering_rpc
 102 {
 103         $_ = shift;
 104         $entering_rpc  = /Handling RPC/;
 105         if($entering_rpc) {
 106                 $oldpid=$pid;
 107                 $pid = extractpid($_);
 108                 $leaving_rpc = 0;
 109         }
 110 }
 111
 112 sub leaving_rpc
 113 {
 114         $_ = shift;
 115         $leaving_rpc  = /Handled RPC/;
 116         if($leaving_rpc) {
 117                 $pid = $oldpid;
 118                 $entering_rpc = 0;
 119         }
 120 }
 121
 122 sub entering
 123 {
 124     $_ = shift;
 125     $entering = /Process entered/;
 126 }
 127
 128 sub leaving
 129 {
 130     $_ = shift;
 131     $entering = /Process leaving/;
 132 }
 133
 134 sub getsubsys
 135 {
 136     my ($subsys, $mask) = split ":";
 137     return hex($subsys);
 138 }
 139
 140 sub getmask
 141 {
 142     my ($subsys, $mask) = split ":";
 143     return hex($mask);
 144 }
 145
 146 sub setcolor
 147 {
 148     my $linemask = shift;
 149     my $line = shift;
 150     if ($linemask == $masks->{TRACE}) {
 151         if(leaving($line)){
 152            print color("yellow on_black");
 153         } else {
 154            print color("green on_black");
 155         }
 156     }
 157     if ($linemask == $masks->{DLMTRACE}) {
 158         print color("magenta on_black");
 159     }
 160     if ($linemask == $masks->{DLM}) {
 161         print color("magenta on_black");
 162     }
 163     if ($linemask == $masks->{DENTRY}) {
 164         print color("red on_black");
 165     }
 166 }
 167
 168 sub study_lock
 169 {
 170     $_ = shift;
 171     my $rc;
 172
 173     $rc = /completion callback handler START ns: (.*) lock: (.*) lrc: (.*) mode/;
 174     if ($rc) {
 175         $completion_callbacks{$1}->{$2} = $3;
 176 #         print color("white");
 177 #         print "---CP CB START: $1 $2 $3\n";
 178 #         print color("reset");
 179     }
 180     $rc = /callback handler finished.* ns: (.*) lock: (.*) lrc: (.*) mode/;
 181     if ($rc) {
 182 #         print color("white");
 183 #         print "---CP CB END: $1 $2 $3 deleting $completion_callbacks{$1}->{$2}\n";
 184 #         print color("reset");
 185         delete $completion_callbacks{$1}->{$2};
 186     }
 187
 188     if ($rc) {
 189         $rc = /client blocking AST callback handler START ns: (.*) lock: (.*) lrc: (.*) mode/;
 190         $blocking_callbacks{$1}->{$2} = $3;
 191 #         print color("white");
 192 #         print "---BL CB START: $1 $2\n";
 193 #         print color("reset");
 194     }
 195     $rc = /client blocking callback handler END ns: (.*) lock: (.*) lrc: (.*) mode/;
 196     if ($rc) {
 197 #         print color("white");
 198 #         print "---BL CB END: $1 $2 $3 deleting $blocking_callbacks{$1}->{$2}\n";
 199 #         print color("reset");
 200         delete $blocking_callbacks{$1}->{$2};
 201     }
 202
 203     $rc = /ldlm_lock_addref.*ns: (.*) lock: (.*) lrc: (.*) mode/;
 204 #     print color("white");
 205 #     print "------>addref ns: $1 lock: $2 lrc: $3\n" if ($rc);
 206 #     print color("reset");
 207     $locks{$1}->{$2} = {$3} if ($rc);
 208     $rc = /ldlm_lock_decref.*ns: (.*) lock: (.*) lrc: (.*) mode/;
 209 #     print color("white");
 210 #     print "------>decref ns: $1 lock: $2 lrc: $3\n" if ($rc);
 211 #     print color("reset");
 212     $locks{$1}->{$2} = {$3} if ($rc);
 213 }
 214
 215 sub hanging_locks
 216 {
 217     my $found;
 218     my $ns;
 219
 220     foreach (keys %completion_callbacks) {
 221         $ns = $_;
 222         $found = 0;
 223         foreach (keys %{$completion_callbacks{$ns}}) {
 224             if (!$found) {
 225                 print "Unfinished completions in ns $ns: \n";
 226                 $found =1;
 227             }
 228             print "  lock: $_ lrc: $completion_callbacks{$ns}->{$_}\n";
 229         }
 230     }
 231     foreach (keys %blocking_callbacks) {
 232         $ns = $_;
 233         $found = 0;
 234         foreach (keys %{$blocking_callbacks{$ns}}) {
 235             if (!$found) {
 236                 print "Unfinished blocking in ns $ns: \n";
 237                 $found =1;
 238             }
 239             printf("  lock: $_ lrc: %s\n", $blocking_callbacks{$ns}->{$_});
 240         }
 241     }
 242
 243 }
 244
 245 sub study_intent
 246 {
 247     $_ = shift;
 248     my $rc;
 249
 250     $rc = /D_IT UP dentry (.*) fsdata/;
 251     delete $it{$1} if ($rc);
 252     $rc = /D_IT DOWN dentry (.*) fsdata/;
 253     $it{$1} = "yes"  if ($rc);
 254 }
 255
 256 sub unmatched_intents {
 257     my $found;
 258     foreach (keys %it) {
 259         if (!$found) {
 260             print "Unmatched intents: \n";
 261             $found =1;
 262         }
 263         print "  $_\n";
 264     }
 265 }
 266
 267 sub usage
 268 {
 269    print "Usage : llanalyze LOGFILE\n";
 270    exit;
 271 }
 272
 273 if ($ARGV[0]) {
 274     if(!open(LOG, "<$ARGV[0]")){
 275       print "Cannot open $ARGV[0]\n";
 276       exit;
 277     }
 278 } else {
 279     usage();
 280 }
 281 $width = 0;
 282 if ($ARGV[1]) {
 283    $width = $ARGV[1];
 284 }
 285
 286 print "nodlm $nodlm, nonet $nonet, trace $trace\n";
 287 print "pid: $pid, dlm_ns: $dlm_ns\n";
 288 print "extract_start: $extract_start\n";
 289 print "extract_end:   $extract_end\n";
 290 while (<LOG>) {
 291     if ($extract_start && $extract_start != LLANAYZE_FOUND) {
 292         next if (index($_, $extract_start, 0) == -1);
 293         $extract_start = LLANAYZE_FOUND;
 294     }
 295
 296     if ($extract_end) {
 297         next if ($extract_end == LLANAYZE_FOUND);
 298         if (index($_, $extract_end, 0) != -1) {
 299              $extract_end = LLANAYZE_FOUND;
 300         }
 301     }
 302
 303     $linepid = extractpid($_);
 304
 305     $linehpid = extracthostpid($_);
 306     $linesubsys = extractsubsys($_);
 307     $linemask = extractmask($_);
 308
 309     if (leaving($_)) {
 310         chop $prefix->{$linepid};
 311         chop $prefix->{$linepid};
 312     }
 313
 314     if ($linemask == $masks->{DENTRY}) {
 315         study_intent($_);
 316     }
 317     if ($linemask == $masks->{DLMTRACE}) {
 318         study_lock($_);
 319     }
 320
 321     if ( !$pid || $linepid == $pid || $linehpid == $pid) {
 322         next if (!$entering_rpc && $rpctrace && $linemask != $masks->{RPCTRACE});
 323         next if ($trace && $linemask != $masks->{TRACE});
 324         next if ($nodlm &&
 325                  (  $linesubsys == $subsys->{LDLM}));
 326         next if ($dlm_ns &&
 327                  (  $linesubsys != $subsys->{LDLM}));
 328         next if (($found_dlm_ns = index( $_, $dlm_ns, 0)) == -1);
 329         next if ($noclass &&
 330                  (  $linesubsys == $subsys->{CLASS}));
 331         next if ($nonet &&
 332                  (  $linesubsys == $subsys->{RPC} ||
 333                     $linesubsys == $subsys->{NET} ||
 334                     $linesubsys == $subsys->{PORTALS} ||
 335                     $linesubsys == $subsys->{SOCKNAL} ||
 336                     $linesubsys == $subsys->{QSWNAL} ||
 337                     $linesubsys == $subsys->{IBNAL} ||
 338                     $linesubsys == $subsys->{GMNAL}));
 339         if(!$entering_rpc) {entering_rpc($_);}
 340         if(!$leaving_rpc) {leaving_rpc($_);}
 341
 342 #        printf "sub/mask: %s - %s\n", getsubsys($_), getmask($_);
 343         if (!$silent) {
 344             setcolor($linemask, $_);
 345             my $string = $prefix->{$linepid}.$_;
 346             if($width){
 347                $string = substr($string, 0, $width)."\n";
 348             }
 349             printf("%s", $string);
 350             print color("reset");
 351         }
 352             #        last if $count++ > 100;
 353     }
 354     if (entering($_)) {
 355         $prefix->{$linepid} .= '  ';
 356     }
 357 }
 358
 359
 360 unmatched_intents();
 361 hanging_locks();
 362 # printf "argv %s pid %d\n", $ARGV[0], extractpid($ARGV[0]);