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