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