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