1#!/usr/bin/perl 2# Copyright (c) 2006 Sampo Kellomaki (sampo@iki.fi). All Rights Reserved. 3# 1. Thread activity in AK lines, busiest thread 4# 2. All per-thread time deltas over -w limit 5# 3. Bar graph of total and per thread activity per time slice (e.g. ms) 6# 4. Lock holding times, contention, frequency, time contribution, bell curve... 7# 5. Lock affinity between threads 8# 9# TODO 10# * call-anal.pl local_callgraph: potential locks held, locks that may be taken 11# 12# mpage -1 -l -L 200 -W 300 -S new-edit.lock | nc kotips 9100 13# mpage -1 -L 300 -W 200 -S new-edit.lock | nc kotips 9100 14 15use Data::Dumper; 16 17$tag = 'ALLSEEN'; 18$format = 'full'; 19$slice = 100; 20$norm = 100; # Normalization factor 21$w_usec = 1000; 22$narrative_lines = 498; 23$compact = 0; 24$max_cols = 20; 25 26$usage = <<USAGE; 27Usage: ak-lock.pl [OPTS] <ak.out 28E.g: ak-lock.pl -w 10000 -t ALLSEEN <sal_monte.out 29 -c Compact time scale in lock narratives 30 -i THR Specify a thread of interest. Can be specified multiple times. 31 If -i is not specified, all threads are considered interesting. 32 -l LINES How many first lines to show in narrative histories. Default $narrative_lines. 33 -n NORM Normalization factor for scaling the bar graphs. Default $norm 34 -r B E Analyze range of time. B is start, E is end time in HHMMSSUUUUUU format. 35 -s USEC Time slice for activity bargraph. Default $slice us 36 -t TAG What tag to start the analysis with. Default is $tag. Try also FIRSTWRAP. 37 -w USEC Wait time. Specify that only delays longer than USEC are output (default $w_usec) 38USAGE 39 ; 40 41while (defined $ARGV[0]) { 42 if ($ARGV[0] eq '-c') { shift; $compact = !$compact; next; } 43 if ($ARGV[0] eq '-i') { shift; $t = shift; $interest{$t} = 1; next; } 44 if ($ARGV[0] eq '-l') { shift; $narrative_lines = shift; next; } 45 if ($ARGV[0] eq '-n') { shift; $norm = shift; next; } 46 if ($ARGV[0] eq '-q') { shift; ++$quiet; next; } # Do not invoke in vain! The disclaimer is important! --Sampo 47 if ($ARGV[0] eq '-r') { shift; undef $tag; $begin_time = shift; $end_time = shift; next; } 48 if ($ARGV[0] eq '-s') { shift; $slice = shift; next; } 49 if ($ARGV[0] eq '-t') { shift; $tag = shift; next; } 50 if ($ARGV[0] eq '-w') { shift; $w_usec = shift; next; } 51 die "Unknown option($ARGV[0])\n$usage"; 52} 53 54### Output preamble, displaying copyright, warranty, confidentiality and other info 55 56print "A P P L I C A T I O N B L A C K (K) B O X A N A L Y S I S R E P O R T (R2)\n" if !$quiet; 57print "#################################################################################\n" if !$quiet; 58print 'Generated using ak-lock.pl $Id$' . "\n\n" if !$quiet; 59 60$_ = <STDIN>; 61print if !/^PREAMBLE (\S+)/ && !$quiet; 62$format = $1 if defined $1; 63 64while ($_ = <STDIN>) { 65 last if /^END_PREAMBLE/o; 66 print if !$quiet; 67} 68 69print <<CAVEAT if !$quiet; 70 71The data in this analysis is based on logged activity of each thread. Threads 72have different roles and may log more or less verbosely based on the role 73and possibly debugging related command line flags. Thus, if a thread appears 74busy, you can only judge that in relation to other threads with the same role. 75CAVEAT 76 ; 77 78# Logarithmic bars. oo == infinite or out of scale 79$bar10 = '----------==========**********##########$$$$$$$$$$ oo'; 80$bar5 = '-----=====*****#####$$$$$ oo'; 81$bar2 = '--==**##$$ oo'; 82$bar1 = '-=*#$ oo'; 83%pdu_state_tab = ( C=>':', l=>'|', L=>'|', U=>'.', M=>'.', m=>' ', F=>' ', '='=>' ' ); 84%state_tab = ( C=>':', l=>'|', L=>'|', U=>'.' ); 85 86# First, skip log entries until TAG or Begin time. 87 88if ($tag) { 89 while ($_ = <STDIN>) { 90 last if /^$tag/o; 91 } 92 $line = <STDIN>; # First line 93} else { 94 while ($line = <STDIN>) { 95 analyze_line($line); 96 last if $time ge $begin_time; 97 } 98} 99 100while ($line =~ /^\s*$/) { # Skip over empty lines 101 $line = <STDIN>; 102} 103 104sub time_diff { 105 my ($t1, $t2, $now) = @_; 106 my $ret; 107 if ($format eq 'brief') { 108 $ret = int(($t1 - $t2) * 1000000); 109 goto err if $t1 < $t2; 110 return $ret; 111 } else { 112 my ($hour1, $min1, $sec1, $gnapa1, $usec1) = unpack "A2A2A2AA6", $t1; 113 my ($hour2, $min2, $sec2, $gnapa2, $usec2) = unpack "A2A2A2AA6", $t2; 114 $usecs1=($hour1*60*60+$min1*60+$sec1)*1000000+$usec1; 115 $usecs2=($hour2*60*60+$min2*60+$sec2)*1000000+$usec2; 116 $ret = $usecs1-$usecs2; 117 goto err if $usecs1 < $usecs2; 118 return $ret; 119 } 120err: 121 my ($p, $f, $l) = caller; 122 #print "WARNING: later($t1) < earlier($t2). now($now) called from $f:$l\n" if $t1 < $t2; 123 return $ret; 124} 125 126sub bars_head { 127 my $h = sprintf " %s N (total) ", ' ' x length($time); 128 my $thr; 129 for $thr (sort keys %act) { 130 $h .= sprintf " %-7s", $thr; 131 } 132 return $h . "\n"; 133} 134 135sub take_lock { 136 my ($thr, $time, $lock, $reason) = @_; 137 $take{$lock} = $time; 138 ++$n{$lock}{$thr}; 139 ++$reason{$lock}{$reason}; 140 if (!$holder{$lock} && !keys %{$contend{$lock}}) { 141 $holder{$lock} = $thr; 142 $narrative{$lock}{$time} .= "$thr L\n"; 143 } else { 144 if ($contend{$lock}{$thr}) { 145 die "WARNING: $lock appears to be already taken/contended by this same thread($thr). Now($time), contended($contend{$lock}{$thr})\n"; 146 } 147 ++$contend_n{$lock}{$thr}; # Count number of contentions by thread 148 $contend{$lock}{$thr} = $time; # Mark thread as contending for rest of comput 149 $narrative{$lock}{$time} .= "$thr C\n"; 150 $narrative_note{$lock}{$time} .= " $holder{$lock}"; # Who is causing contention 151 } 152} 153 154sub let_go_of_lock { 155 my ($thr, $time, $lock) = @_; 156 if ($holder{$lock}) { 157 if ($holder{$lock} eq $thr) { 158 undef $holder{$lock}; 159 die "WARNING: take{$lock} not set when unlocking: $thr $time\n" if !$take{$lock}; 160 $h_diff = time_diff($time, $take{$lock}, $time); 161 } else { 162 #die "$lock appears to be released by different thread than which took it: $time holder($holder{$lock}) unlocker($thr)\n"; 163 #print "ADJUST: $thr $time: $lock unlock by different thread than which took it: apparent holder($holder{$lock}) unlocker($thr)\n"; 164 165 # Can be caused by two threads taking lock on same usec. E.g. L1+L2+U2 166 # implies that, in fact, L1 was taken after L2 (and L1 should be contending) 167 # and L2 should NOT be contending. 168 169 $contend{$lock}{$holder{$lock}} = $time; # L1 is contending 170 delete $contend{$lock}{$thr}; # L2 not contending. 171 undef $holder{$lock}; 172 $h_diff = 0; # No reliable estimate can be made 173 } 174 $c_diff = 0; 175 } else { # Determine which of the main lock contenders got it. 176 if ($contend{$lock}{$thr}) { 177 # We contended to get the lock. Later it was unlocked and we got the lock. 178 if ($unlock{$lock}) { 179 $c_diff = time_diff($unlock{$lock}, $contend{$lock}{$thr}, "$time $unlock_by{$lock} $holder{$lock}"); 180 if ($c_diff < 0) { # Obviously there was no contention 181 #print "IGNORE: $thr $time: Ignoring negative contention time($c_diff).\n"; 182 $c_diff = 0; 183 $h_diff = time_diff($time, $take{$lock}, $time); 184 } else { 185 $h_diff = time_diff($time, $unlock{$lock}, $time); 186 } 187 $narrative{$lock}{$unlock{$lock}} .= "$thr l\n"; 188 } else { 189 die "WARNING: $lock was contended and unlocked by thr($thr) time($time), but there is no previous unlock time.\n"; 190 $c_diff = time_diff($time, $contend{$lock}{$thr}, $time); 191 $h_diff = 0; # No reliable estimate can be made, we account all time to contention 192 } 193 delete $contend{$lock}{$thr}; 194 } else { 195 #die "WARNING: $lock released without being held: $thr $time\nmlh($main_lock_holder) contend(" . Dumper(%main_lock_contend) . ")"; 196 print "WARNING: $thr $time: $lock released without apparently being held (wrap around?) contend(".Dumper(%{$contend{$lock}}).")\n" if $rel_wo_held_warn{$lock}{$thr}++; 197 $h_diff = 0; # No reliable estimate can be made 198 $c_diff = 0; 199 } 200 } 201 $narrative{$lock}{$time} .= "$thr U\n"; 202 $time{$lock}{$thr} += $h_diff; 203 $unlock{$lock} = $time; # Most recent unlock time: may be the lock time of contender 204 $unlock_by{$lock} = $thr; 205 #$bin = $h_diff ? log($h_diff)/log(10) : 0; *** rethink log scaling 206 #++$held{$lock}{$bin}; 207 ++$held_usec{$lock}{$h_diff}; 208 $held_ts{$lock}{$h_diff} = $time; 209 ++$contend_usec{$lock}{$c_diff}; 210 $contend_ts{$lock}{$c_diff} = $time; 211} 212 213sub analyze_line { 214 my ($line) = @_; 215 return if !$line || substr($line, 0, 1) eq '#'; 216 if ($format eq 'brief') { 217 ($thr, $time, $funcline, $op, @rest) = split /\s+/, $line; 218 if ($time < $prev_time) { 219 warn "time($time) < prev_time($prev_time)"; 220 $time = "1$time"; 221 } 222 $prev_time = $time; 223 } else { 224 ($thr, $yyyymmdd, $time, $fileline, $func, $op, @rest) = split /\s+/, $line; 225 } 226 return if $thr eq 'ALLSEEN' || $thr eq 'FIRSTWRAP'; 227 $t_diff = $old{$thr} ? time_diff($time, $old{$thr}, $time) : 0; 228 $old{$thr} = $time; # N.B. $time is either hhmmssuu or ssuu depending on format 229 #warn "thr($thr) $line"; 230 if ($t_diff >= $w_usec) { 231 print " $t_diff \t$line" if !defined %interest || $interest{$thr}; 232 } 233 ++$act{$thr}; 234 ++$act_slice{$thr}; 235 ++$activity_in_slice; 236 if ($slice && $last_time ne $time && !(($time*1000000) % $slice)) { 237 $bars_hdr = bars_head(); 238 if ($bars_hdr ne $old_bars_hdr) { 239 #warn "new($bars_hdr)\nold($bars_hdr)"; 240 $bars .= $bars_hdr; 241 $old_bars_hdr = $bars_hdr; 242 } 243 244 $bars .= sprintf " $time %4d %-15s", $activity_in_slice, '#' x ($activity_in_slice/$norm); 245 $activity_in_slice = 0; 246 for $thr (sort keys %act) { 247 $bars .= sprintf " %3s %-3s", $act_slice{$thr} ? $act_slice{$thr} : '.', '#' x ($act_slice{$thr} / $norm); 248 $act_slice{$thr} = 0; 249 } 250 $bars .= "\n"; 251 $last_time = $time; 252 } 253 254 if ($op eq 'SHUFF_LOCK') { 255 take_lock($thr, $time, 'shuff_lock', $rest[1]); 256 return; 257 } 258 if ($op eq 'SHUFF_UNLOCK') { 259 let_go_of_lock($thr, $time, 'shuff_lock'); 260 return; 261 } 262 263 if ($op eq 'MAIN_LOCK') { 264 take_lock($thr, $time, 'main_lock', $rest[1]); 265 return; 266 } 267 if ($op eq 'MAIN_UNLOCK') { 268 let_go_of_lock($thr, $time, 'main_lock'); 269 return; 270 } 271 272 if ($op =~ /^MEM_LOCK\((?:0x)?([0-9a-f]+)\)/) { 273 if ($pdu_thr{$1} ne $thr) { 274 $pdu_narr{$time} .= "$thr $1 <$thr>\n"; 275 $pdu_thr{$1} = $thr; 276 } 277 $pdu_narr{$time} .= "$thr $1 M\n"; 278 (undef, $lock) = split /=/, $rest[1]; 279 take_lock($thr, $time, "mem_lock_$lock", $rest[3]); 280 return; 281 } 282 if ($op =~ /^MEM_UNLK\((?:0x)?([0-9a-f]+)\)/) { 283 if ($pdu_thr{$1} ne $thr) { 284 $pdu_narr{$time} .= "$thr $1 <$thr>\n"; 285 $pdu_thr{$1} = $thr; 286 } 287 $pdu_narr{$time} .= "$thr $1 m\n"; 288 (undef, $lock) = split /=/, $rest[1]; 289 let_go_of_lock($thr, $time, "mem_lock_$lock"); 290 return; 291 } 292 293 if ($op =~ /^MALLOC\((?:0x)?([0-9a-f]+)\)/) { 294 return; 295 } 296 if ($op =~ /^MEM_FREE\((?:0x)?([0-9a-f]+)\)/) { 297 return; 298 } 299 if ($op =~ /^MEM_FRM_POOL\((?:0x)?([0-9a-f]+)\)/) { 300 return; 301 } 302 if ($op =~ /^MEM_REL\((?:0x)?([0-9a-f]+)\)/) { 303 return; 304 } 305 306 if ($op eq 'FD_POOL_LOCK') { 307 $lock = substr($rest[1], 4); 308 take_lock($thr, $time, "fd_pool_$lock", $rest[2]); 309 return; 310 } 311 if ($op eq 'FD_POOL_UNLOCK') { 312 $lock = substr($rest[1], 4); 313 let_go_of_lock($thr, $time, "fd_pool_$lock"); 314 return; 315 } 316 317 if ($op eq 'THR_POOL_LOCK') { 318 $lock = substr($rest[1], 4); 319 take_lock($thr, $time, "thr_pool_$lock", $rest[2]); 320 return; 321 } 322 if ($op eq 'THR_POOL_UNLOCK') { 323 $lock = substr($rest[1], 4); 324 let_go_of_lock($thr, $time, "thr_pool_$lock"); 325 return; 326 } 327 328 if ($op eq 'RUN_LOCK') { 329 if ($rest[3] eq '[ds_global_get]' || $rest[3] eq '[ds_global_put]') { 330 take_lock($thr, $time, 'global_run_lock', $rest[3]); 331 } 332 return; 333 } 334 if ($op eq 'RUN_UNLOCK') { 335 if ($rest[3] eq '[ds_global_get]' || $rest[3] eq '[ds_global_put]') { 336 let_go_of_lock($thr, $time, 'global_run_lock'); 337 } 338 return; 339 } 340 341 if ($op eq 'GC_START') { 342 $gc_start = $time; # *** does not handle ovelapping gc due to insufficient log data 343 return; 344 } 345 if ($op eq 'GC_END') { 346 ++$gc_duration{time_diff($time, $gc_start)}; 347 return; 348 } 349 350 if ($op eq 'POLL_OK') { 351 ($n) = $rest[0] =~ /n_evs=(\d+)/; 352 ++$poll_ok{$rest[1]}{$n}; 353 return; 354 } 355 356 # I/O objects 357 358 if ($op =~ /^DSIO_LOCK\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 359 ++$dsio_lock_reason{$rest[4]}; 360 return; 361 } 362 if ($op =~ /^DSIO_UNLK\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 363 return; 364 } 365 if ($op =~ /^DSQIO_LOCK\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 366 ++$dsqio_lock_reason{$rest[4] || $rest[2]}; 367 return; 368 } 369 if ($op =~ /^DSQIO_UNLK\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 370 return; 371 } 372 if ($op =~ /^READ\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 373 return; 374 } 375 if ($op =~ /^WR_FRM_BUF\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 376 return; 377 } 378 if ($op =~ /^ENQ_IO\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { # poller produces fd 379 return; 380 } 381 if ($op =~ /^DEQ_IO\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { # consumer consumes fd 382 return; 383 } 384 if ($op =~ /^DSIO_FREE\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 385 return; 386 } 387 if ($op =~ /^AGAIN\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 388 return; 389 } 390 if ($op =~ /^EAGAIN_POLL\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 391 return; 392 } 393 if ($op =~ /^FE\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 394 return; 395 } 396 if ($op =~ /^THE_IO\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 397 return; 398 } 399 if ($op =~ /^TRY_TERM\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 400 return; 401 } 402 if ($op =~ /^CLOSE_CONN\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 403 return; 404 } 405 if ($op =~ /^TCP_EOF\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 406 return; 407 } 408 if ($op =~ /^ACCEPT\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 409 return; 410 } 411 if ($op =~ /^MARK_FOR_TERM\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 412 return; 413 } 414 if ($op =~ /^RAISE_XCPT_IO\(([0-9a-f]+).(?:0x)?([0-9a-f]+)\)/) { 415 return; 416 } 417 418 # PDU life cycle 419 420 if ($op =~ /^NEW_BUF_LK\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/ 421 || $op =~ /^NEW_BUF\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 422 ++$pdus{$2}; 423 if ($pdu_thr{$2} ne $thr) { 424 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 425 $pdu_thr{$2} = $thr; 426 } 427 $pdu_narr{$time} .= "$thr $2 *\n"; 428 $pdu_creat{$2} = $time; 429 $pdu_story{$2} = []; 430 $pdu_story_timing{$2} = []; 431 return; 432 } 433 434 if ($op =~ /^LDAP_TRAILING\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 435 if ($pdu_thr{$2} ne $thr) { 436 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 437 $pdu_thr{$2} = $thr; 438 } 439 $pdu_narr{$time} .= "$thr $2 d\n"; 440 push @{$pdu_story{$2}}, 'd'; 441 push @{$pdu_story_timing{$2}}, $time; 442 return; 443 } 444 if ($op =~ /^LDAP_DECODE\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 445 if ($pdu_thr{$2} ne $thr) { 446 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 447 $pdu_thr{$2} = $thr; 448 } 449 $pdu_narr{$time} .= "$thr $2 d\n"; 450 push @{$pdu_story{$2}}, 'd'; 451 push @{$pdu_story_timing{$2}}, $time; 452 return; 453 } 454 455 if ($op =~ /^LDAP_ENCODE\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 456 if ($pdu_thr{$2} ne $thr) { 457 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 458 $pdu_thr{$2} = $thr; 459 } 460 $pdu_narr{$time} .= "$thr $2 e\n"; 461 push @{$pdu_story{$2}}, 'e'; 462 push @{$pdu_story_timing{$2}}, $time; 463 return; 464 } 465 466 if ($op =~ /^BE_SETUP\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 467 if ($pdu_thr{$2} ne $thr) { 468 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 469 $pdu_thr{$2} = $thr; 470 } 471 $pdu_narr{$time} .= "$thr $2 V\n"; 472 push @{$pdu_story{$2}}, 'V'; 473 push @{$pdu_story_timing{$2}}, $time; 474 return; 475 } 476 477 if ($op =~ /^BE_POP\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 478 if ($pdu_thr{$2} ne $thr) { 479 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 480 $pdu_thr{$2} = $thr; 481 } 482 $pdu_narr{$time} .= "$thr $2 v\n"; 483 push @{$pdu_story{$2}}, 'v'; 484 push @{$pdu_story_timing{$2}}, $time; 485 return; 486 } 487 488 if ($op =~ /^HK_PROCESS\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 489 if ($pdu_thr{$2} ne $thr) { 490 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 491 $pdu_thr{$2} = $thr; 492 } 493 $pdu_narr{$time} .= "$thr $2 H$1\n"; 494 push @{$pdu_story{$2}}, "H$1"; 495 push @{$pdu_story_timing{$2}}, $time; 496 return; 497 } 498 if ($op =~ /^NEXT_HK\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 499 if ($pdu_thr{$2} ne $thr) { 500 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 501 $pdu_thr{$2} = $thr; 502 } 503 $pdu_narr{$time} .= "$thr $2 h\n"; 504 push @{$pdu_story{$2}}, 'h'; 505 push @{$pdu_story_timing{$2}}, $time; 506 return; 507 } 508 if ($op =~ /^CS_REJECT\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 509 if ($pdu_thr{$2} ne $thr) { 510 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 511 $pdu_thr{$2} = $thr; 512 } 513 $pdu_narr{$time} .= "$thr $2 R\n"; 514 push @{$pdu_story{$2}}, 'R'; 515 push @{$pdu_story_timing{$2}}, $time; 516 return; 517 } 518 if ($op =~ /^CS_SKIP_SUFFIX\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 519 if ($pdu_thr{$2} ne $thr) { 520 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 521 $pdu_thr{$2} = $thr; 522 } 523 $pdu_narr{$time} .= "$thr $2 z\n"; 524 push @{$pdu_story{$2}}, 'z'; 525 push @{$pdu_story_timing{$2}}, $time; 526 return; 527 } 528 529 if ($op =~ /^PDU_LOCK\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 530 if ($pdu_thr{$2} ne $thr) { 531 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 532 $pdu_thr{$2} = $thr; 533 } 534 $pdu_narr{$time} .= "$thr $2 L\n"; 535 ++$pdu_lock_reason{$rest[9]}; 536 push @{$pdu_story{$2}}, 'L'; 537 push @{$pdu_story_timing{$2}}, $time; 538 return; 539 } 540 if ($op =~ /^PDU_UNLK\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 541 if ($pdu_thr{$2} ne $thr) { 542 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 543 $pdu_thr{$2} = $thr; 544 } 545 $pdu_narr{$time} .= "$thr $2 U\n"; 546 push @{$pdu_story{$2}}, 'U'; 547 push @{$pdu_story_timing{$2}}, $time; 548 return; 549 } 550 551 if ($op =~ /^RUN_LOCK\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 552 if ($pdu_thr{$2} ne $thr) { 553 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 554 $pdu_thr{$2} = $thr; 555 } 556 $pdu_narr{$time} .= "$thr $2 L\n"; 557 ++$pdu_lock_reason{$rest[4]}; 558 push @{$pdu_story{$2}}, 'L'; 559 push @{$pdu_story_timing{$2}}, $time; 560 return; 561 } 562 if ($op =~ /^RUN_UNLOCK\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 563 if ($pdu_thr{$2} ne $thr) { 564 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 565 $pdu_thr{$2} = $thr; 566 } 567 $pdu_narr{$time} .= "$thr $2 U\n"; 568 push @{$pdu_story{$2}}, 'U'; 569 push @{$pdu_story_timing{$2}}, $time; 570 return; 571 } 572 573 if ($op =~ /^PDU_INVOKE\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 574 if ($pdu_thr{$2} ne $thr) { 575 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 576 $pdu_thr{$2} = $thr; 577 } 578 $pdu_narr{$time} .= "$thr $2 I\n"; 579 push @{$pdu_story{$2}}, 'I'; 580 push @{$pdu_story_timing{$2}}, $time; 581 return; 582 } 583 if ($op =~ /^FULL\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 584 if ($pdu_thr{$2} ne $thr) { 585 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 586 $pdu_thr{$2} = $thr; 587 } 588 $pdu_narr{$time} .= "$thr $2 J\n"; 589 push @{$pdu_story{$2}}, 'J'; 590 push @{$pdu_story_timing{$2}}, $time; 591 return; 592 } 593 if ($op =~ /^LEAF\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 594 if ($pdu_thr{$2} ne $thr) { 595 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 596 $pdu_thr{$2} = $thr; 597 } 598 $pdu_narr{$time} .= "$thr $2 j\n"; 599 push @{$pdu_story{$2}}, 'j'; 600 push @{$pdu_story_timing{$2}}, $time; 601 return; 602 } 603 604 if ($op =~ /^SYNTH_RESP\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 605 if ($pdu_thr{$2} ne $thr) { 606 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 607 $pdu_thr{$2} = $thr; 608 } 609 $pdu_narr{$time} .= "$thr $2 s\n"; 610 push @{$pdu_story{$2}}, 's'; 611 push @{$pdu_story_timing{$2}}, $time; 612 return; 613 } 614 615 if ($op =~ /^HOPELESS\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 616 if ($pdu_thr{$2} ne $thr) { 617 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 618 $pdu_thr{$2} = $thr; 619 } 620 $pdu_narr{$time} .= "$thr $2 x\n"; 621 push @{$pdu_story{$2}}, 'x'; 622 push @{$pdu_story_timing{$2}}, $time; 623 return; 624 } 625 626 if ($op =~ /^TRY_REL_REQ_ET_PEND_DONE\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 627 if ($pdu_thr{$2} ne $thr) { 628 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 629 $pdu_thr{$2} = $thr; 630 } 631 $pdu_narr{$time} .= "$thr $2 g\n"; 632 push @{$pdu_story{$2}}, 'g'; 633 push @{$pdu_story_timing{$2}}, $time; 634 return; 635 } 636 637 if ($op =~ /^PDU_ENQ\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 638 if ($pdu_thr{$2} ne $thr) { 639 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 640 $pdu_thr{$2} = $thr; 641 } 642 $pdu_narr{$time} .= "$thr $2 E\n"; 643 push @{$pdu_story{$2}}, 'E'; 644 push @{$pdu_story_timing{$2}}, $time; 645 return; 646 } 647 if ($op =~ /^CHOOSE_BE\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 648 if ($pdu_thr{$2} ne $thr) { 649 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 650 $pdu_thr{$2} = $thr; 651 } 652 $pdu_narr{$time} .= "$thr $2 B\n"; 653 push @{$pdu_story{$2}}, 'B'; 654 push @{$pdu_story_timing{$2}}, $time; 655 return; 656 } 657 if ($op =~ /^SCHED_LK\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 658 if ($pdu_thr{$2} ne $thr) { 659 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 660 $pdu_thr{$2} = $thr; 661 } 662 $pdu_narr{$time} .= "$thr $2 S\n"; 663 push @{$pdu_story{$2}}, 'S'; 664 push @{$pdu_story_timing{$2}}, $time; 665 return; 666 } 667 if ($op =~ /^FE_POP\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 668 if ($pdu_thr{$2} ne $thr) { 669 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 670 $pdu_thr{$2} = $thr; 671 } 672 $pdu_narr{$time} .= "$thr $2 P\n"; 673 push @{$pdu_story{$2}}, 'P'; 674 push @{$pdu_story_timing{$2}}, $time; 675 return; 676 } 677 if ($op =~ /^DQ_TO_WR\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 678 if ($pdu_thr{$2} ne $thr) { 679 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 680 $pdu_thr{$2} = $thr; 681 } 682 $pdu_narr{$time} .= "$thr $2 D\n"; 683 push @{$pdu_story{$2}}, 'D'; 684 push @{$pdu_story_timing{$2}}, $time; 685 return; 686 } 687 if ($op =~ /^FE_POP2\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 688 if ($pdu_thr{$2} ne $thr) { 689 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 690 $pdu_thr{$2} = $thr; 691 } 692 $pdu_narr{$time} .= "$thr $2 p\n"; 693 push @{$pdu_story{$2}}, 'p'; 694 push @{$pdu_story_timing{$2}}, $time; 695 return; 696 } 697 if ($op =~ /^RM_FRM_Q\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 698 if ($pdu_thr{$2} ne $thr) { 699 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 700 $pdu_thr{$2} = $thr; 701 } 702 $pdu_narr{$time} .= "$thr $2 Q\n"; 703 push @{$pdu_story{$2}}, 'Q'; 704 push @{$pdu_story_timing{$2}}, $time; 705 return; 706 } 707 if ($op =~ /^ONE_MORE\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 708 if ($pdu_thr{$2} ne $thr) { 709 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 710 $pdu_thr{$2} = $thr; 711 } 712 $pdu_narr{$time} .= "$thr $2 O\n"; 713 push @{$pdu_story{$2}}, 'O'; 714 push @{$pdu_story_timing{$2}}, $time; 715 return; 716 } 717 if ($op =~ /^YANK\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 718 if ($pdu_thr{$2} ne $thr) { 719 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 720 $pdu_thr{$2} = $thr; 721 } 722 $pdu_narr{$time} .= "$thr $2 Y\n"; 723 push @{$pdu_story{$2}}, 'Y'; 724 push @{$pdu_story_timing{$2}}, $time; 725 return; 726 } 727 728 if ($op =~ /^ADD_TO_WR\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 729 if ($pdu_thr{$2} ne $thr) { 730 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 731 $pdu_thr{$2} = $thr; 732 } 733 $pdu_narr{$time} .= "$thr $2 W\n"; 734 push @{$pdu_story{$2}}, 'W'; 735 push @{$pdu_story_timing{$2}}, $time; 736 return; 737 } 738 739 if ($op =~ /^CLEAN_PDU\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 740 if ($pdu_thr{$2} ne $thr) { 741 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 742 $pdu_thr{$2} = $thr; 743 } 744 $pdu_narr{$time} .= "$thr $2 f\n"; 745 $bin = int(time_diff($time, $pdu_creat{$2})/100)*100; 746 #warn "creat($pdu_creat{$2}) now($time) pdu($1:$2)" if $bin > 100000; 747 ++$pdu_live_time{$1}{$bin} if $pdu_creat{$2}; 748 ++$n_pdu{$1}; 749 push @{$pdu_story{$2}}, 'f'; 750 push @{$pdu_story_timing{$2}}, $time; 751 return; 752 } 753 if ($op =~ /^TRY_REL\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 754 if ($pdu_thr{$2} ne $thr) { 755 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 756 $pdu_thr{$2} = $thr; 757 } 758 $pdu_narr{$time} .= "$thr $2 r\n"; 759 push @{$pdu_story{$2}}, 'r'; 760 push @{$pdu_story_timing{$2}}, $time; 761 return; 762 } 763 if ($op =~ /^UNLINK\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 764 if ($pdu_thr{$2} ne $thr) { 765 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 766 $pdu_thr{$2} = $thr; 767 } 768 $pdu_narr{$time} .= "$thr $2 u\n"; 769 push @{$pdu_story{$2}}, 'u'; 770 push @{$pdu_story_timing{$2}}, $time; 771 return; 772 } 773 if ($op =~ /^FREE_BUF\(([0-9a-f]+):(?:0x)?([0-9a-f]+)\)/) { 774 if ($pdu_thr{$2} ne $thr) { 775 $pdu_narr{$time} .= "$thr $2 <$thr>\n"; 776 $pdu_thr{$2} = $thr; 777 } 778 $pdu_narr{$time} .= "$thr $2 =$1\n"; 779 return if !$pdu_creat{$2}; # Incomplete history 780 781 ++$pdu_alloc_time{$1}{int(time_diff($time, $pdu_creat{$2})/100)*100}; 782 push @{$pdu_story{$2}}, '='; 783 push @{$pdu_story_timing{$2}}, $time; 784 785 $story = '*' . join('', @{$pdu_story{$2}}); 786 $pdu_story_ops{$story} = $pdu_story{$2}; # Copy the array 787 ++$pdu_story_n{$story}; 788 #warn "Story($story) length=$#{@{$pdu_story{$2}}} creat($pdu_creat{$2})"; 789 790 $now = $pdu_creat{$2}; 791 $delta = time_diff($time, $now); 792 die "Impossible delta($delta) time($time) now($now)" if $delta <= 0; 793 #warn "delta($delta) Tmin($pdu_story_Tmin{$story}{'=='})"; 794 $pdu_story_Tmin{$story}{'=='} = $delta if !defined($pdu_story_Tmin{$story}{'=='}) 795 || $delta < $pdu_story_Tmin{$story}{'=='}; 796 $pdu_story_Tmax{$story}{'=='} = $delta if $delta > $pdu_story_Tmax{$story}{'=='}; 797 $pdu_story_Ttot{$story}{'=='} += $delta; 798 799 for ($i = 0; $i <= $#{@{$pdu_story{$2}}}; ++$i) { 800 $op = $pdu_story{$2}[$i]; 801 $delta = time_diff($pdu_story_timing{$2}[$i], $now); 802 die "Impossible delta($delta) pdu=$2 i=$i time($pdu_story_timing{$2}[$i]) now($now) creat($pdu_creat{$2})" if $delta < 0; 803 $now = $pdu_story_timing{$2}[$i]; 804 $pdu_story_Tmin{$story}{$op} = $delta if !defined($pdu_story_Tmin{$story}{$op}) 805 || $delta < $pdu_story_Tmin{$story}{$op}; 806 $pdu_story_Tmax{$story}{$op} = $delta if $delta > $pdu_story_Tmax{$story}{$op}; 807 $pdu_story_Ttot{$story}{$op} += $delta; 808 } 809 return; 810 } 811 ++$unexplained_ops{$op}; 812} 813 814# Narrative Legend 815# A=, B=choose_be, C=contend lock, D=dequeue, d=decode, E=enqueue, e=encode F=(was free), f=clean, 816# G=, g=TRY_REL_REQ_ET_PEND_DONE, H=hk_process, h=next_hk, I=Invoke, J=Full, j=leaf, K=, L=lock, l=lock after contend, 817# M=MemLock, m=MemUnlock, N=, O=one more, o=other, P=fe_populate, p=fe_pop2, Q=rm_fr_q, 818# R=CS_Reject, r=try_release, S=sched, s=synth resp, T=thread change, 819# U=unlock, u=unlink, V=BE_SETUP, v=be_pop, W=write_pdu, X=raise xcpt, x=hopeless, Y=yank, Z=, z=skip suffix 820# '='=free '*'=new 821 822### Process the first line 823 824print "\n1 Thread Delay in Excess of $w_usec us\n===================================\n\n"; 825print " Diff Thr Time...\n"; 826 827$yyyymmdd = 'n/a (brief format)'; 828 829$0 ="ak-lock: starting"; 830analyze_line($line); 831if ($format eq 'brief') { 832 $first_yyyymmdd = 'n/a (brief format)'; 833} else { 834 $first_yyyymmdd = $yyyymmdd; 835} 836$first_time = $time; 837#warn "first_time($first_time) line($line)"; 838 839### Scan all lines and build summary data 840 841while ($line = <STDIN>) { 842 analyze_line($line); 843 $0 ="ak-lock: line $time"; 844 last if defined($end_time) && $time ge $end_time; 845} 846$t_diff = time_diff($time, $first_time, 'conclude'); 847$0 ="ak-lock: line scan over"; 848 849for $k (sort keys %unexplained_ops) { 850 print " unexplained($k): $unexplained_ops{$k}\n"; 851} 852 853print "\n2 Activity Overview\n===================\n\n"; 854print $bars; 855print $bars_hdr; 856 857### Activity by thread 858 859print "WARNING: Date changed during analysis period. Analysis timings are unreliable.\nFirst date $first_yyyymmdd, last date $yyyymmdd.\n" if $first_yyyymmdd ne $yyyymmdd; 860 861# N.B. Total activity by FIRSTWRAP is pointless because all threads have same size buffers. 862print "\n3 Total Activity by Thread\n==========================\n\n Thr N\n" if !defined($tag) || $tag eq 'ALLSEEN'; 863 864$tot = 0; 865for $thr (sort keys %act) { 866 next if !$thr; 867 printf " %4s %6d\n", $thr, $act{$thr} if !defined($tag) || $tag eq 'ALLSEEN'; 868 $tot += $act{$thr}; 869} 870 871### Lock analysis 872 873print "\n4 Locks Contended and Held\n==========================\n"; 874 875for $lock (sort keys %narrative) { 876 lock_report(++$subsec, $lock); 877} 878 879sub bar_len { 880 my ($n, $fact) = @_; 881 return $fact * log($n?$n:1) / log(10); 882} 883 884sub report_lock_time_range_bins { 885 my ($bin_width, $upper_lim, $report_lim) = @_; 886 while ($i <= $#ticks) { 887 $lim += $bin_width; 888 last if $lim >= $upper_lim; 889 890 my $held = 0; 891 my $n_held = 0; 892 my $held_note = ''; 893 my $contend = 0; 894 my $n_contend = 0; 895 my $contend_note = ''; 896 897 for (; $i <= $#ticks; ++$i) { 898 last if $ticks[$i] >= $lim; 899 if ($held_usec{$lock}{$ticks[$i]}) { 900 $held += $held_usec{$lock}{$ticks[$i]}; 901 $held_note .= "$held_ts{$lock}{$ticks[$i]} "; 902 ++$n_held; 903 } 904 if ($contend_usec{$lock}{$ticks[$i]}) { 905 $contend += $contend_usec{$lock}{$ticks[$i]}; 906 $contend_note .= "$contend_ts{$lock}{$ticks[$i]} "; 907 ++$n_contend; 908 } 909 } 910 911 if ($n_held && $n_held < $report_lim) { 912 chop $held_note; 913 $held_note = " ($held_note)"; 914 } else { 915 $held_note = ''; 916 } 917 if ($n_contend && $n_contend < $report_lim) { 918 chop $contend_note; 919 $contend_note = " ($contend_note)"; 920 } else { 921 $contend_note = ''; 922 } 923 924 printf(" %5s %5s %-45s %5s %-45s\n", $lim - 10, 925 $held ? $held : '.', substr($bar10, 0, bar_len($held, 5)) . $held_note, 926 $contend ? $contend : '.', substr($bar10, 0, bar_len($contend, 5)). $contend_note); 927 } 928} 929 930sub lock_report { 931 my ($subsec, $lock) = @_; 932 print "\n4.$subsec $lock\n----------------------\n"; 933 934 print "\n4.$subsec.1 $lock contended & held (us, log10 bars)\n~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n\n"; 935 print " us N contended N held\n"; 936 937 %ticks = (); 938 for $k (keys %{$held_usec{$lock}}) { 939 $ticks{$k} = 1; 940 } 941 for $k (keys %{$contend_usec{$lock}}) { 942 $ticks{$k} = 1; 943 } 944 945 @ticks = sort { $a <=> $b } keys %ticks; 946 for ($i = 0; $i <= $#ticks; ++$i) { 947 last if $ticks[$i] >= 10; 948 printf(" %5s %5s %-45s %5s %-45s\n", $ticks[$i], 949 $held_usec{$lock}{$ticks[$i]} ? $held_usec{$lock}{$ticks[$i]} : '.', 950 substr($bar10, 0, bar_len($held_usec{$lock}{$ticks[$i]}, 5)), 951 $contend_usec{$lock}{$ticks[$i]} ? $contend_usec{$lock}{$ticks[$i]} : '.', 952 substr($bar10, 0, bar_len($contend_usec{$lock}{$ticks[$i]}, 5))); 953 } 954 955 print " 10-99 us, with 10 us bins\n"; 956 957 $lim = 10; 958 while ($i <= $#ticks) { 959 $lim += 10; 960 last if $lim > 99; 961 962 $held = $contend = 0; 963 for (; $i <= $#ticks; ++$i) { 964 last if $ticks[$i] >= $lim; 965 $held += $held_usec{$lock}{$ticks[$i]}; 966 $contend += $contend_usec{$lock}{$ticks[$i]}; 967 } 968 printf(" %5s %5s %-45s %5s %-45s\n", $lim - 10, 969 $held ? $held : '.', substr($bar10, 0, bar_len($held, 5)), 970 $contend ? $contend : '.', substr($bar10, 0, bar_len($contend, 5))); 971 } 972 973 print " Summary: 100-999us, with 100us bins\n"; 974 report_lock_time_range_bins(100, 1000, 3); 975 print " Summary: 1000-4999us, with 500us bins\n"; 976 report_lock_time_range_bins(500, 5000, 3); 977 print " Summary: 5-10ms, with 1ms bins\n"; 978 report_lock_time_range_bins(1000, 10000, 3); 979 print " Summary: over 10ms, with 10ms bins\n"; 980 report_lock_time_range_bins(10000, 1000000000, 3); 981 982 print "\n4.$subsec.2 $lock by number of times taken, avg, and total held (log10 bars)\n~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n\n"; 983 print " Thread N Avg (us) Total held (us)\n"; 984 985 for $thr (sort keys %{$n{$lock}}) { 986 $n = $n{$lock}{$thr}; 987 $t = $time{$lock}{$thr}; 988 $avg = $t / $n; 989 printf(" %5s %7d %-25s %3.1f %-20s %7d %-20s\n", $thr, 990 $n, substr($bar5, 0, 5 * log($n) / log(10)), 991 $avg, substr($bar5, 0, 20 * (log(1+$avg)) / log(10)), 992 $t, substr($bar5, 0, 5 * log($t) / log(10))); 993 } 994 995 print "\n4.$subsec.3 $lock by reason taken (log10 bars)\n~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n\n"; 996 print " Reason N\n"; 997 998 for $reason (sort keys %{$reason{$lock}}) { 999 $n = $reason{$lock}{$reason}; 1000 printf(" %30s %7d %-25s\n", $reason, $n, substr($bar5, 0, 5 * log($n) / log(10))); 1001 } 1002 1003 print "\n4.$subsec.4 $lock narrative history (lines 100..".($narrative_lines+100) 1004 .")\n~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n\n"; 1005 1006 my $hdr = ' ' . (' ' x length($time)); 1007 my @thrs = sort keys %act; 1008 for $thr (@thrs) { 1009 $hdr .= sprintf " %-7s", $thr; 1010 $state{$thr} = ' '; 1011 } 1012 $hdr .= "\n"; 1013 1014 print $hdr; 1015 my $n = 0; 1016 my $last_time = 0; 1017 @ticks = sort keys %{$narrative{$lock}}; 1018 $n_start = (length @ticks > $narrative_lines + 100) ? 100 : 0; 1019 for $time (@ticks) { 1020 if (!$compact && $last_time) { # Print inactive usecs 1021 for (; $last_time < $time; $last_time += 0.000001) { 1022 printf " %.6f", $last_time; 1023 for $thr (@thrs) { 1024 printf " %-7s", $state{$thr}; 1025 } 1026 print "-\n"; 1027 } 1028 } 1029 $last_time = $time + 0.000001; 1030 1031 for $thr (@thrs) { 1032 $thr_act{$thr} = ''; 1033 } 1034 @evts = split /\n/, $narrative{$lock}{$time}; 1035 for $evt (@evts) { 1036 ($thr, $e) = split /\s+/, $evt; 1037 $thr_act{$thr} .= $e; 1038 $state{$thr} = $state_tab{$e}; 1039 } 1040 next if --$n_start > 0; 1041 1042 print " $time"; 1043 for $thr (@thrs) { 1044 printf " %-7s", $thr_act{$thr} ? $thr_act{$thr} : $state{$thr}; 1045 } 1046 print "\n"; 1047 print $hdr if ++$n % 100 == 0; 1048 last if $n > $narrative_lines; 1049 } 1050 1051 print $hdr; 1052 print <<LEGEND; 1053 1054 Legend: L=lock taken straight, C=Locking attempted but contention, 1055 l=lock taken after contention, U=unlock, .=no relevant activity. 1056LEGEND 1057 ; 1058} 1059 1060$0 ="ak-lock: PDUs"; 1061print "\n5 PDUs\n======\n\n"; 1062 1063@pdus = sort keys %pdus; 1064#warn "pdus: " . Dumper(\@pdus); 1065 1066print "\n5.1 Types of PDUs\n----------------\n\n"; 1067 1068print " op N (log10 bars)\n"; 1069$tot = 0; 1070for $op (sort keys %n_pdu) { 1071 printf " %3s %7d %s\n", $op, $n_pdu{$op}, substr($bar10, 0, 5 * log($n_pdu{$op}) / log(10)); 1072 $tot += $n_pdu{$op}; 1073} 1074printf "\nTotal PDUs processed: %d (%d ops/sec)\n", $tot, $tot * 10000000 / $t_diff; 1075printf "Number of PDU objects used: %d (reused %.1f times)\n", $#pdus+1, $tot/$#pdus+1; 1076 1077print "\n5.2 PDU lock by reason taken\n----------------------------\n\n"; 1078print " Reason N (log10 bars)\n"; 1079 1080for $reason (sort keys %pdu_lock_reason) { 1081 $n = $pdu_lock_reason{$reason}; 1082 printf(" %30s %7d %-25s\n", $reason, $n, substr($bar5, 0, 5 * log($n) / log(10))); 1083} 1084 1085#for $pdu (@pdus) { print "pdu($pdu)\n"; } 1086 1087print "\n5.3 PDU Stories\n---------------\n\n"; 1088 1089print "\n5.3.1 PDU life time and allocated time by operation\n~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n\n"; 1090 1091%ops = (); 1092for $k (keys %pdu_live_time) { 1093 $ops{$k} = 1; 1094} 1095for $k (keys %pdu_alloc_time) { 1096 $ops{$k} = 1; 1097} 1098 1099for $op (sort keys %ops) { 1100 printf "\n %-3s us N live (log10 bars) N allocated (log10 bars)\n", $op; 1101 1102 %ticks = (); 1103 for $k (keys %{$pdu_live_time{$op}}) { 1104 $ticks{$k} = 1; 1105 } 1106 for $k (keys %{$pdu_alloc_time{$op}}) { 1107 $ticks{$k} = 1; 1108 } 1109 1110 $live_tot = $alloc_tot = 0; 1111 for $usec (sort { $a <=> $b } keys %ticks) { 1112 $live = $pdu_live_time{$op}{$usec}; 1113 $alloc = $pdu_alloc_time{$op}{$usec}; 1114 $live_tot += $live; 1115 $alloc_tot += $alloc; 1116 printf(" %7d %7s %-25s %7s %-25s\n", $usec, 1117 $live?$live:'', substr($bar10, 0, 5 * log(1+$live) / log(10)), 1118 $alloc?$alloc:'', substr($bar10, 0, 5 * log(1+$alloc) / log(10))); 1119 } 1120 printf " TOTALS: %d %d\n", $live_tot, $alloc_tot; 1121} 1122 1123print "\n5.3.2 Summary of PDU Stories\n~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n\n"; 1124 1125print " N (log10 bars) TAmin TAavg TAmax Story\n"; 1126for $story (sort keys %pdu_story_n) { 1127 printf(" %7d %-40s %5d %9.1f %7d %7d %s\n", 1128 $pdu_story_n{$story}, 1129 substr($bar10, 0, 5 * log(1+$pdu_story_n{$story}) / log(10)), 1130 $pdu_story_Tmin{$story}{'=='}, 1131 $pdu_story_Ttot{$story}{'=='} / $pdu_story_n{$story}, 1132 $pdu_story_Tmax{$story}{'=='}, 1133 $story); 1134} 1135 1136print "\n5.3.3 PDU Story Timings\n~~~~~~~~~~~~~~~~~~~~~~~\n"; 1137 1138for $story (sort keys %pdu_story_n) { 1139 print "\n Story: $story (N=$pdu_story_n{$story})\n op Tmin Tavg Tmax (Tavg log10 bar)\n"; 1140 printf " %-4s ", '*'; 1141 %op_count = (); 1142 for $op (@{$pdu_story_ops{$story}}) { 1143 ++$op_count{$op}; 1144 } 1145 for $op (@{$pdu_story_ops{$story}}) { #@{$pdu_story{$2}} 1146 $avg = $pdu_story_Ttot{$story}{$op} / ($pdu_story_n{$story} * $op_count{$op}); 1147 printf("%5d %9.1f %7d %s\n", 1148 $pdu_story_Tmin{$story}{$op}, $avg, $pdu_story_Tmax{$story}{$op}, 1149 substr($bar10, 0, 5 * log(1+$avg) / log(10))); 1150 printf " %-4s ", $op; 1151 } 1152 print "\n"; 1153} 1154 1155print "\n5.4 Narrative PDU History\n--------------------------\n\n"; 1156 1157@ticks = sort keys %pdu_narr; 1158 1159if (0) { 1160 for ($j = 0; $j <= $#pdus; $j += 20) { 1161 $0 ="ak-lock: pdus($j)"; 1162 $hdr = '' . (' ' x length($time)); 1163 for ($i = $j; $i < $j+20; ++$i) { 1164 $hdr .= sprintf " %8s", $pdus[$i]; 1165 $pdu_state{$pdus[$i]} = ' '; 1166 } 1167 $hdr .= "\n"; 1168 1169 print $hdr; 1170 $n = 0; 1171 $last_time = 0; 1172 1173 $n_start = (length @ticks > $narrative_lines + 100) ? 100 : 0; 1174 for $time (@ticks) { 1175 if (!$compact && $last_time) { # Print inactive usecs 1176 for (; $last_time < $time; $last_time += 0.000001) { 1177 printf " %.6f", $last_time; 1178 for $pdu (@pdus) { 1179 printf " %-8s", $pdu_state{$pdu}; 1180 } 1181 print "-\n"; 1182 } 1183 } 1184 $last_time = $time + 0.000001; 1185 1186 for ($i = $j; $i < $j+20; ++$i) { 1187 $pdu_act{$pdus[$i]} = ''; 1188 } 1189 @evts = split /\n/, $pdu_narr{$time}; 1190 for $evt (@evts) { 1191 ($thr, $pdu, $e) = split /\s+/, $evt; 1192 $pdu_act{$pdu} .= $e; 1193 $pdu_state{$pdu} = $pdu_state_tab{$e} || '.'; 1194 } 1195 next if --$n_start > 0; 1196 1197 print " $time"; 1198 for ($i = $j; $i < $j+20; ++$i) { 1199 printf " %-8s", $pdu_act{$pdus[$i]} ? $pdu_act{$pdus[$i]} : $pdu_state{$pdus[$i]}; 1200 } 1201 print "\n"; 1202 print $hdr if ++$n % 100 == 0; 1203 last if $n > $narrative_lines; 1204 } 1205 print $hdr; 1206 } 1207} else { 1208 # Display PDUs using a "cache" of display slots. Any PDU that is 1209 # in F (free) state is eligible to give its slot. As secondary 1210 # criteria, LRU is used. 1211 1212 @slots = (); # Each slot holds ptr value of PDU 1213 @last_seen = (); # Time value of last action for LRU purposes 1214 1215 #$n_start = (length @ticks > $narrative_lines + 100) ? 100 : 0; 1216 1217 $old_hdr = 0; 1218 $n = 0; 1219 $last_time = 0; 1220 for $time (@ticks) { 1221 $0 ="ak-lock: PDU $time $#slots"; 1222 if (!$compact && $last_time) { # Print inactive usecs 1223 for (; $last_time < $time; $last_time += 0.000001) { 1224 printf " %.6f", $last_time; 1225 for $pdu (@slots) { 1226 printf " %-8s", $pdu_state{$pdu}; 1227 } 1228 print "-\n"; 1229 } 1230 } 1231 $last_time = $time + 0.000001; 1232 1233 for $pdu (@pdus) { 1234 $pdu_act{$pdu} = ''; 1235 } 1236 @evts = split /\n/, $pdu_narr{$time}; 1237 for $evt (@evts) { 1238 ($thr, $pdu, $e) = split /\s+/, $evt; 1239 $pdu_act{$pdu} .= $e; 1240 $pdu_state{$pdu} = $pdu_state_tab{$e} || '.'; 1241 } 1242 1243 for $pdu (@pdus) { 1244 next if $pdu_state{$pdu} eq ' ' || $pdu_state{$pdu} eq ''; 1245 next if $pdu_slot{$pdu} && $slots[$pdu_slot{$pdu}] eq $pdu; # We still have old slot 1246 # Identify empty slots 1247 %empties = (); 1248 for ($i = 0; $i <= $#slots; ++$i) { 1249 $empties{$i} = $last_seen[$i] if $slots[$i] eq '' || $pdu_state{$slots[$i]} eq ' '; 1250 } 1251 @empty_slots = sort { $empties{$a} <=> $empties{$b} } keys %empties; # LRU 1252 if (defined $empty_slots[0]) { 1253 $slots[$empty_slots[0]] = $pdu; 1254 $pdu_slot{$pdu} = $empty_slots[0]; 1255 #warn "$time Assigned PDU($pdu) slot($empty_slots[0])"; 1256 } else { # No empty slot available. We simply need one more slot. 1257 push @slots, $pdu; 1258 $pdu_slot{$pdu} = $#slots; 1259 #warn "$time Assigned PDU($pdu) slot($#slots) due to no empty slots"; 1260 #for $pdu (@slots) { warn " $pdu: pdu_state($pdu_state{$pdu})"; } 1261 } 1262 } 1263 1264 $cols = $max_cols; 1265 $hdr = ' ' . (' ' x length($time)); 1266 for $pdu (@slots) { 1267 $hdr .= sprintf " %8s", $pdu; 1268 last if !--$cols; 1269 } 1270 print "$hdr ($#slots)\n" if $hdr ne $old_hdr; 1271 $old_hdr = $hdr; 1272 1273 #next if --$n_start > 0; 1274 1275 $line = ''; 1276 $cols = $#slots < $max_cols-1 ? $#slots : $max_cols-1; 1277 for ($i = 0; $i <= $cols; ++$i) { 1278 $pdu = $slots[$i]; 1279 $line .= sprintf " %-8s", $pdu_act{$pdu} ? $pdu_act{$pdu} : $pdu_state{$pdu}; 1280 $last_seen[$i] = $time if $pdu_act{$pdu}; 1281 } 1282 $line .= "\n"; 1283 print " $time$line" if !$compact || $line ne $prev_line; 1284 $prev_line = $line; 1285 #print $hdr if ++$n % 100 == 0; 1286 #last if $n > $narrative_lines; 1287 } 1288 print $hdr; 1289} 1290 1291$0 ="ak-lock: PDUs done"; 1292 1293print <<LEGEND; 1294 1295 Legend: B=choose_be, C=contend lock, D=dequeue, E=enqueue, f=clean, 1296 H=hk_process, h=next_hk, L=lock, l=lock after contend, 1297 P=fe_populate, p=fe_pop2, U=unlock, .=no relevant activity *=new, ==free 1298 1299 Final slots: $#slots 1300LEGEND 1301 ; 1302 1303print "\n6 I/O Objects\n===================\n\n"; 1304 1305print "\n6.1 DSIO lock by reason taken\n-------------------------------\n\n"; 1306print " Reason N (log10 bars)\n"; 1307 1308for $reason (sort keys %dsio_lock_reason) { 1309 $n = $dsio_lock_reason{$reason}; 1310 printf(" %30s %7d %-25s\n", $reason, $n, substr($bar5, 0, 5 * log($n) / log(10))); 1311} 1312 1313print "\n6.2 DSQIO lock by reason taken\n-------------------------------\n\n"; 1314print " Reason N (log10 bars)\n"; 1315 1316for $reason (sort keys %dsqio_lock_reason) { 1317 $n = $dsqio_lock_reason{$reason}; 1318 printf(" %30s %7d %-25s\n", $reason, $n, substr($bar5, 0, 5 * log($n) / log(10))); 1319} 1320 1321print "\n7 Other Metrics\n===============\n\n"; 1322 1323print "\n7.1 Garbage Collects\n--------------------\n\n"; 1324 1325print " Duration N (log10 bars)\n"; 1326$tot = 0; 1327for $d (sort { $a <=> $b } keys %gc_duration) { 1328 printf " %4s %6d %s\n", $d, $gc_duration{$d}, substr($bar10, 0, 5 * log(1+$gc_duration{$d}) / log(10)); 1329 $tot += $act{$thr}; 1330} 1331 1332print " Total $tot garbage collects\n"; 1333 1334print "\n7.2 Polls\n---------\n\n"; 1335 1336$i = 0; 1337for $poll (sort keys %poll_ok) { 1338 ++$i; 1339 print "\n7.2.$i POLL_OK $poll\n~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n\n"; 1340 1341 $tot = 0; 1342 print " Events N_occur (log10 bars)\n"; 1343 for $n (sort { $a <=> $b } keys %{$poll_ok{$poll}}) { 1344 printf " %4s %6d %s\n", $n, $poll_ok{$poll}{$n}, substr($bar10, 0, 5 * log(1+$poll_ok{$poll}{$n}) / log(10));; 1345 $tot += $poll_ok{$poll}{$n}; 1346 } 1347 print " Total $tot polls\n"; 1348} 1349 1350### Final report 1351 1352print "\n9 Concluding Remarks\n====================\n"; 1353 1354$ops_sec = int($tot * 1000000 / $t_diff); 1355 1356print <<REPORT; 1357 1358 Total lines analyzed: $tot 1359 Time covered: $t_diff usec 1360 Activity rate: $ops_sec lines/sec 1361 Date: $yyyymmdd 1362 First time: $first_time 1363 Last time: $time 1364 1365END OF REPORT 1366REPORT 1367 ; 1368 1369__END__ 1370