1#!/usr/bin/perl 2# This is a POC for reading the text representation of trace output related to 3# page reclaim. It makes an attempt to extract some high-level information on 4# what is going on. The accuracy of the parser may vary 5# 6# Example usage: trace-vmscan-postprocess.pl < /sys/kernel/debug/tracing/trace_pipe 7# other options 8# --read-procstat If the trace lacks process info, get it from /proc 9# --ignore-pid Aggregate processes of the same name together 10# 11# Copyright (c) IBM Corporation 2009 12# Author: Mel Gorman <mel@csn.ul.ie> 13use strict; 14use Getopt::Long; 15 16# Tracepoint events 17use constant MM_VMSCAN_DIRECT_RECLAIM_BEGIN => 1; 18use constant MM_VMSCAN_DIRECT_RECLAIM_END => 2; 19use constant MM_VMSCAN_KSWAPD_WAKE => 3; 20use constant MM_VMSCAN_KSWAPD_SLEEP => 4; 21use constant MM_VMSCAN_LRU_SHRINK_ACTIVE => 5; 22use constant MM_VMSCAN_LRU_SHRINK_INACTIVE => 6; 23use constant MM_VMSCAN_LRU_ISOLATE => 7; 24use constant MM_VMSCAN_WRITEPAGE_FILE_SYNC => 8; 25use constant MM_VMSCAN_WRITEPAGE_ANON_SYNC => 9; 26use constant MM_VMSCAN_WRITEPAGE_FILE_ASYNC => 10; 27use constant MM_VMSCAN_WRITEPAGE_ANON_ASYNC => 11; 28use constant MM_VMSCAN_WRITEPAGE_ASYNC => 12; 29use constant EVENT_UNKNOWN => 13; 30 31# Per-order events 32use constant MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER => 11; 33use constant MM_VMSCAN_WAKEUP_KSWAPD_PERORDER => 12; 34use constant MM_VMSCAN_KSWAPD_WAKE_PERORDER => 13; 35use constant HIGH_KSWAPD_REWAKEUP_PERORDER => 14; 36 37# Constants used to track state 38use constant STATE_DIRECT_BEGIN => 15; 39use constant STATE_DIRECT_ORDER => 16; 40use constant STATE_KSWAPD_BEGIN => 17; 41use constant STATE_KSWAPD_ORDER => 18; 42 43# High-level events extrapolated from tracepoints 44use constant HIGH_DIRECT_RECLAIM_LATENCY => 19; 45use constant HIGH_KSWAPD_LATENCY => 20; 46use constant HIGH_KSWAPD_REWAKEUP => 21; 47use constant HIGH_NR_SCANNED => 22; 48use constant HIGH_NR_TAKEN => 23; 49use constant HIGH_NR_RECLAIM => 24; 50use constant HIGH_NR_CONTIG_DIRTY => 25; 51 52my %perprocesspid; 53my %perprocess; 54my %last_procmap; 55my $opt_ignorepid; 56my $opt_read_procstat; 57 58my $total_wakeup_kswapd; 59my ($total_direct_reclaim, $total_direct_nr_scanned); 60my ($total_direct_latency, $total_kswapd_latency); 61my ($total_direct_writepage_file_sync, $total_direct_writepage_file_async); 62my ($total_direct_writepage_anon_sync, $total_direct_writepage_anon_async); 63my ($total_kswapd_nr_scanned, $total_kswapd_wake); 64my ($total_kswapd_writepage_file_sync, $total_kswapd_writepage_file_async); 65my ($total_kswapd_writepage_anon_sync, $total_kswapd_writepage_anon_async); 66 67# Catch sigint and exit on request 68my $sigint_report = 0; 69my $sigint_exit = 0; 70my $sigint_pending = 0; 71my $sigint_received = 0; 72sub sigint_handler { 73 my $current_time = time; 74 if ($current_time - 2 > $sigint_received) { 75 print "SIGINT received, report pending. Hit ctrl-c again to exit\n"; 76 $sigint_report = 1; 77 } else { 78 if (!$sigint_exit) { 79 print "Second SIGINT received quickly, exiting\n"; 80 } 81 $sigint_exit++; 82 } 83 84 if ($sigint_exit > 3) { 85 print "Many SIGINTs received, exiting now without report\n"; 86 exit; 87 } 88 89 $sigint_received = $current_time; 90 $sigint_pending = 1; 91} 92$SIG{INT} = "sigint_handler"; 93 94# Parse command line options 95GetOptions( 96 'ignore-pid' => \$opt_ignorepid, 97 'read-procstat' => \$opt_read_procstat, 98); 99 100# Defaults for dynamically discovered regex's 101my $regex_direct_begin_default = 'order=([0-9]*) may_writepage=([0-9]*) gfp_flags=([A-Z_|]*)'; 102my $regex_direct_end_default = 'nr_reclaimed=([0-9]*)'; 103my $regex_kswapd_wake_default = 'nid=([0-9]*) order=([0-9]*)'; 104my $regex_kswapd_sleep_default = 'nid=([0-9]*)'; 105my $regex_wakeup_kswapd_default = 'nid=([0-9]*) zid=([0-9]*) order=([0-9]*)'; 106my $regex_lru_isolate_default = 'isolate_mode=([0-9]*) order=([0-9]*) nr_requested=([0-9]*) nr_scanned=([0-9]*) nr_taken=([0-9]*) contig_taken=([0-9]*) contig_dirty=([0-9]*) contig_failed=([0-9]*)'; 107my $regex_lru_shrink_inactive_default = 'lru=([A-Z_]*) nr_scanned=([0-9]*) nr_reclaimed=([0-9]*) priority=([0-9]*)'; 108my $regex_lru_shrink_active_default = 'lru=([A-Z_]*) nr_scanned=([0-9]*) nr_rotated=([0-9]*) priority=([0-9]*)'; 109my $regex_writepage_default = 'page=([0-9a-f]*) pfn=([0-9]*) flags=([A-Z_|]*)'; 110 111# Dyanically discovered regex 112my $regex_direct_begin; 113my $regex_direct_end; 114my $regex_kswapd_wake; 115my $regex_kswapd_sleep; 116my $regex_wakeup_kswapd; 117my $regex_lru_isolate; 118my $regex_lru_shrink_inactive; 119my $regex_lru_shrink_active; 120my $regex_writepage; 121 122# Static regex used. Specified like this for readability and for use with /o 123# (process_pid) (cpus ) ( time ) (tpoint ) (details) 124my $regex_traceevent = '\s*([a-zA-Z0-9-]*)\s*(\[[0-9]*\])\s*([0-9.]*):\s*([a-zA-Z_]*):\s*(.*)'; 125my $regex_statname = '[-0-9]*\s\((.*)\).*'; 126my $regex_statppid = '[-0-9]*\s\(.*\)\s[A-Za-z]\s([0-9]*).*'; 127 128sub generate_traceevent_regex { 129 my $event = shift; 130 my $default = shift; 131 my $regex; 132 133 # Read the event format or use the default 134 if (!open (FORMAT, "/sys/kernel/debug/tracing/events/$event/format")) { 135 print("WARNING: Event $event format string not found\n"); 136 return $default; 137 } else { 138 my $line; 139 while (!eof(FORMAT)) { 140 $line = <FORMAT>; 141 $line =~ s/, REC->.*//; 142 if ($line =~ /^print fmt:\s"(.*)".*/) { 143 $regex = $1; 144 $regex =~ s/%s/\([0-9a-zA-Z|_]*\)/g; 145 $regex =~ s/%p/\([0-9a-f]*\)/g; 146 $regex =~ s/%d/\([-0-9]*\)/g; 147 $regex =~ s/%ld/\([-0-9]*\)/g; 148 $regex =~ s/%lu/\([0-9]*\)/g; 149 } 150 } 151 } 152 153 # Can't handle the print_flags stuff but in the context of this 154 # script, it really doesn't matter 155 $regex =~ s/\(REC.*\) \? __print_flags.*//; 156 157 # Verify fields are in the right order 158 my $tuple; 159 foreach $tuple (split /\s/, $regex) { 160 my ($key, $value) = split(/=/, $tuple); 161 my $expected = shift; 162 if ($key ne $expected) { 163 print("WARNING: Format not as expected for event $event '$key' != '$expected'\n"); 164 $regex =~ s/$key=\((.*)\)/$key=$1/; 165 } 166 } 167 168 if (defined shift) { 169 die("Fewer fields than expected in format"); 170 } 171 172 return $regex; 173} 174 175$regex_direct_begin = generate_traceevent_regex( 176 "vmscan/mm_vmscan_direct_reclaim_begin", 177 $regex_direct_begin_default, 178 "order", "may_writepage", 179 "gfp_flags"); 180$regex_direct_end = generate_traceevent_regex( 181 "vmscan/mm_vmscan_direct_reclaim_end", 182 $regex_direct_end_default, 183 "nr_reclaimed"); 184$regex_kswapd_wake = generate_traceevent_regex( 185 "vmscan/mm_vmscan_kswapd_wake", 186 $regex_kswapd_wake_default, 187 "nid", "order"); 188$regex_kswapd_sleep = generate_traceevent_regex( 189 "vmscan/mm_vmscan_kswapd_sleep", 190 $regex_kswapd_sleep_default, 191 "nid"); 192$regex_wakeup_kswapd = generate_traceevent_regex( 193 "vmscan/mm_vmscan_wakeup_kswapd", 194 $regex_wakeup_kswapd_default, 195 "nid", "zid", "order"); 196$regex_lru_isolate = generate_traceevent_regex( 197 "vmscan/mm_vmscan_lru_isolate", 198 $regex_lru_isolate_default, 199 "isolate_mode", "order", 200 "nr_requested", "nr_scanned", "nr_taken", 201 "contig_taken", "contig_dirty", "contig_failed"); 202$regex_lru_shrink_inactive = generate_traceevent_regex( 203 "vmscan/mm_vmscan_lru_shrink_inactive", 204 $regex_lru_shrink_inactive_default, 205 "nid", "zid", 206 "lru", 207 "nr_scanned", "nr_reclaimed", "priority"); 208$regex_lru_shrink_active = generate_traceevent_regex( 209 "vmscan/mm_vmscan_lru_shrink_active", 210 $regex_lru_shrink_active_default, 211 "nid", "zid", 212 "lru", 213 "nr_scanned", "nr_rotated", "priority"); 214$regex_writepage = generate_traceevent_regex( 215 "vmscan/mm_vmscan_writepage", 216 $regex_writepage_default, 217 "page", "pfn", "flags"); 218 219sub read_statline($) { 220 my $pid = $_[0]; 221 my $statline; 222 223 if (open(STAT, "/proc/$pid/stat")) { 224 $statline = <STAT>; 225 close(STAT); 226 } 227 228 if ($statline eq '') { 229 $statline = "-1 (UNKNOWN_PROCESS_NAME) R 0"; 230 } 231 232 return $statline; 233} 234 235sub guess_process_pid($$) { 236 my $pid = $_[0]; 237 my $statline = $_[1]; 238 239 if ($pid == 0) { 240 return "swapper-0"; 241 } 242 243 if ($statline !~ /$regex_statname/o) { 244 die("Failed to math stat line for process name :: $statline"); 245 } 246 return "$1-$pid"; 247} 248 249# Convert sec.usec timestamp format 250sub timestamp_to_ms($) { 251 my $timestamp = $_[0]; 252 253 my ($sec, $usec) = split (/\./, $timestamp); 254 return ($sec * 1000) + ($usec / 1000); 255} 256 257sub process_events { 258 my $traceevent; 259 my $process_pid; 260 my $cpus; 261 my $timestamp; 262 my $tracepoint; 263 my $details; 264 my $statline; 265 266 # Read each line of the event log 267EVENT_PROCESS: 268 while ($traceevent = <STDIN>) { 269 if ($traceevent =~ /$regex_traceevent/o) { 270 $process_pid = $1; 271 $timestamp = $3; 272 $tracepoint = $4; 273 274 $process_pid =~ /(.*)-([0-9]*)$/; 275 my $process = $1; 276 my $pid = $2; 277 278 if ($process eq "") { 279 $process = $last_procmap{$pid}; 280 $process_pid = "$process-$pid"; 281 } 282 $last_procmap{$pid} = $process; 283 284 if ($opt_read_procstat) { 285 $statline = read_statline($pid); 286 if ($opt_read_procstat && $process eq '') { 287 $process_pid = guess_process_pid($pid, $statline); 288 } 289 } 290 } else { 291 next; 292 } 293 294 # Perl Switch() sucks majorly 295 if ($tracepoint eq "mm_vmscan_direct_reclaim_begin") { 296 $timestamp = timestamp_to_ms($timestamp); 297 $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}++; 298 $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN} = $timestamp; 299 300 $details = $5; 301 if ($details !~ /$regex_direct_begin/o) { 302 print "WARNING: Failed to parse mm_vmscan_direct_reclaim_begin as expected\n"; 303 print " $details\n"; 304 print " $regex_direct_begin\n"; 305 next; 306 } 307 my $order = $1; 308 $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order]++; 309 $perprocesspid{$process_pid}->{STATE_DIRECT_ORDER} = $order; 310 } elsif ($tracepoint eq "mm_vmscan_direct_reclaim_end") { 311 # Count the event itself 312 my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_END}; 313 $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_END}++; 314 315 # Record how long direct reclaim took this time 316 if (defined $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN}) { 317 $timestamp = timestamp_to_ms($timestamp); 318 my $order = $perprocesspid{$process_pid}->{STATE_DIRECT_ORDER}; 319 my $latency = ($timestamp - $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN}); 320 $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index] = "$order-$latency"; 321 } 322 } elsif ($tracepoint eq "mm_vmscan_kswapd_wake") { 323 $details = $5; 324 if ($details !~ /$regex_kswapd_wake/o) { 325 print "WARNING: Failed to parse mm_vmscan_kswapd_wake as expected\n"; 326 print " $details\n"; 327 print " $regex_kswapd_wake\n"; 328 next; 329 } 330 331 my $order = $2; 332 $perprocesspid{$process_pid}->{STATE_KSWAPD_ORDER} = $order; 333 if (!$perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN}) { 334 $timestamp = timestamp_to_ms($timestamp); 335 $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}++; 336 $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN} = $timestamp; 337 $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order]++; 338 } else { 339 $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP}++; 340 $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP_PERORDER}[$order]++; 341 } 342 } elsif ($tracepoint eq "mm_vmscan_kswapd_sleep") { 343 344 # Count the event itself 345 my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP}; 346 $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP}++; 347 348 # Record how long kswapd was awake 349 $timestamp = timestamp_to_ms($timestamp); 350 my $order = $perprocesspid{$process_pid}->{STATE_KSWAPD_ORDER}; 351 my $latency = ($timestamp - $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN}); 352 $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index] = "$order-$latency"; 353 $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN} = 0; 354 } elsif ($tracepoint eq "mm_vmscan_wakeup_kswapd") { 355 $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}++; 356 357 $details = $5; 358 if ($details !~ /$regex_wakeup_kswapd/o) { 359 print "WARNING: Failed to parse mm_vmscan_wakeup_kswapd as expected\n"; 360 print " $details\n"; 361 print " $regex_wakeup_kswapd\n"; 362 next; 363 } 364 my $order = $3; 365 $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order]++; 366 } elsif ($tracepoint eq "mm_vmscan_lru_isolate") { 367 $details = $5; 368 if ($details !~ /$regex_lru_isolate/o) { 369 print "WARNING: Failed to parse mm_vmscan_lru_isolate as expected\n"; 370 print " $details\n"; 371 print " $regex_lru_isolate/o\n"; 372 next; 373 } 374 my $nr_scanned = $4; 375 my $nr_contig_dirty = $7; 376 $perprocesspid{$process_pid}->{HIGH_NR_SCANNED} += $nr_scanned; 377 $perprocesspid{$process_pid}->{HIGH_NR_CONTIG_DIRTY} += $nr_contig_dirty; 378 } elsif ($tracepoint eq "mm_vmscan_writepage") { 379 $details = $5; 380 if ($details !~ /$regex_writepage/o) { 381 print "WARNING: Failed to parse mm_vmscan_writepage as expected\n"; 382 print " $details\n"; 383 print " $regex_writepage\n"; 384 next; 385 } 386 387 my $flags = $3; 388 my $file = 0; 389 my $sync_io = 0; 390 if ($flags =~ /RECLAIM_WB_FILE/) { 391 $file = 1; 392 } 393 if ($flags =~ /RECLAIM_WB_SYNC/) { 394 $sync_io = 1; 395 } 396 if ($sync_io) { 397 if ($file) { 398 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}++; 399 } else { 400 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}++; 401 } 402 } else { 403 if ($file) { 404 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}++; 405 } else { 406 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}++; 407 } 408 } 409 } else { 410 $perprocesspid{$process_pid}->{EVENT_UNKNOWN}++; 411 } 412 413 if ($sigint_pending) { 414 last EVENT_PROCESS; 415 } 416 } 417} 418 419sub dump_stats { 420 my $hashref = shift; 421 my %stats = %$hashref; 422 423 # Dump per-process stats 424 my $process_pid; 425 my $max_strlen = 0; 426 427 # Get the maximum process name 428 foreach $process_pid (keys %perprocesspid) { 429 my $len = length($process_pid); 430 if ($len > $max_strlen) { 431 $max_strlen = $len; 432 } 433 } 434 $max_strlen += 2; 435 436 # Work out latencies 437 printf("\n") if !$opt_ignorepid; 438 printf("Reclaim latencies expressed as order-latency_in_ms\n") if !$opt_ignorepid; 439 foreach $process_pid (keys %stats) { 440 441 if (!$stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[0] && 442 !$stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[0]) { 443 next; 444 } 445 446 printf "%-" . $max_strlen . "s ", $process_pid if !$opt_ignorepid; 447 my $index = 0; 448 while (defined $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index] || 449 defined $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]) { 450 451 if ($stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) { 452 printf("%s ", $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) if !$opt_ignorepid; 453 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]); 454 $total_direct_latency += $latency; 455 } else { 456 printf("%s ", $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]) if !$opt_ignorepid; 457 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]); 458 $total_kswapd_latency += $latency; 459 } 460 $index++; 461 } 462 print "\n" if !$opt_ignorepid; 463 } 464 465 # Print out process activity 466 printf("\n"); 467 printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s %8s\n", "Process", "Direct", "Wokeup", "Pages", "Pages", "Pages", "Time"); 468 printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s %8s\n", "details", "Rclms", "Kswapd", "Scanned", "Sync-IO", "ASync-IO", "Stalled"); 469 foreach $process_pid (keys %stats) { 470 471 if (!$stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}) { 472 next; 473 } 474 475 $total_direct_reclaim += $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}; 476 $total_wakeup_kswapd += $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}; 477 $total_direct_nr_scanned += $stats{$process_pid}->{HIGH_NR_SCANNED}; 478 $total_direct_writepage_file_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}; 479 $total_direct_writepage_anon_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}; 480 $total_direct_writepage_file_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}; 481 482 $total_direct_writepage_anon_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}; 483 484 my $index = 0; 485 my $this_reclaim_delay = 0; 486 while (defined $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) { 487 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]); 488 $this_reclaim_delay += $latency; 489 $index++; 490 } 491 492 printf("%-" . $max_strlen . "s %8d %10d %8u %8u %8u %8.3f", 493 $process_pid, 494 $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}, 495 $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}, 496 $stats{$process_pid}->{HIGH_NR_SCANNED}, 497 $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}, 498 $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}, 499 $this_reclaim_delay / 1000); 500 501 if ($stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}) { 502 print " "; 503 for (my $order = 0; $order < 20; $order++) { 504 my $count = $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order]; 505 if ($count != 0) { 506 print "direct-$order=$count "; 507 } 508 } 509 } 510 if ($stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}) { 511 print " "; 512 for (my $order = 0; $order < 20; $order++) { 513 my $count = $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order]; 514 if ($count != 0) { 515 print "wakeup-$order=$count "; 516 } 517 } 518 } 519 if ($stats{$process_pid}->{HIGH_NR_CONTIG_DIRTY}) { 520 print " "; 521 my $count = $stats{$process_pid}->{HIGH_NR_CONTIG_DIRTY}; 522 if ($count != 0) { 523 print "contig-dirty=$count "; 524 } 525 } 526 527 print "\n"; 528 } 529 530 # Print out kswapd activity 531 printf("\n"); 532 printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s\n", "Kswapd", "Kswapd", "Order", "Pages", "Pages", "Pages"); 533 printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s\n", "Instance", "Wakeups", "Re-wakeup", "Scanned", "Sync-IO", "ASync-IO"); 534 foreach $process_pid (keys %stats) { 535 536 if (!$stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}) { 537 next; 538 } 539 540 $total_kswapd_wake += $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}; 541 $total_kswapd_nr_scanned += $stats{$process_pid}->{HIGH_NR_SCANNED}; 542 $total_kswapd_writepage_file_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}; 543 $total_kswapd_writepage_anon_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}; 544 $total_kswapd_writepage_file_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}; 545 $total_kswapd_writepage_anon_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}; 546 547 printf("%-" . $max_strlen . "s %8d %10d %8u %8i %8u", 548 $process_pid, 549 $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}, 550 $stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP}, 551 $stats{$process_pid}->{HIGH_NR_SCANNED}, 552 $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}, 553 $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}); 554 555 if ($stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}) { 556 print " "; 557 for (my $order = 0; $order < 20; $order++) { 558 my $count = $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order]; 559 if ($count != 0) { 560 print "wake-$order=$count "; 561 } 562 } 563 } 564 if ($stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP}) { 565 print " "; 566 for (my $order = 0; $order < 20; $order++) { 567 my $count = $stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP_PERORDER}[$order]; 568 if ($count != 0) { 569 print "rewake-$order=$count "; 570 } 571 } 572 } 573 printf("\n"); 574 } 575 576 # Print out summaries 577 $total_direct_latency /= 1000; 578 $total_kswapd_latency /= 1000; 579 print "\nSummary\n"; 580 print "Direct reclaims: $total_direct_reclaim\n"; 581 print "Direct reclaim pages scanned: $total_direct_nr_scanned\n"; 582 print "Direct reclaim write file sync I/O: $total_direct_writepage_file_sync\n"; 583 print "Direct reclaim write anon sync I/O: $total_direct_writepage_anon_sync\n"; 584 print "Direct reclaim write file async I/O: $total_direct_writepage_file_async\n"; 585 print "Direct reclaim write anon async I/O: $total_direct_writepage_anon_async\n"; 586 print "Wake kswapd requests: $total_wakeup_kswapd\n"; 587 printf "Time stalled direct reclaim: %-1.2f seconds\n", $total_direct_latency; 588 print "\n"; 589 print "Kswapd wakeups: $total_kswapd_wake\n"; 590 print "Kswapd pages scanned: $total_kswapd_nr_scanned\n"; 591 print "Kswapd reclaim write file sync I/O: $total_kswapd_writepage_file_sync\n"; 592 print "Kswapd reclaim write anon sync I/O: $total_kswapd_writepage_anon_sync\n"; 593 print "Kswapd reclaim write file async I/O: $total_kswapd_writepage_file_async\n"; 594 print "Kswapd reclaim write anon async I/O: $total_kswapd_writepage_anon_async\n"; 595 printf "Time kswapd awake: %-1.2f seconds\n", $total_kswapd_latency; 596} 597 598sub aggregate_perprocesspid() { 599 my $process_pid; 600 my $process; 601 undef %perprocess; 602 603 foreach $process_pid (keys %perprocesspid) { 604 $process = $process_pid; 605 $process =~ s/-([0-9])*$//; 606 if ($process eq '') { 607 $process = "NO_PROCESS_NAME"; 608 } 609 610 $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN} += $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}; 611 $perprocess{$process}->{MM_VMSCAN_KSWAPD_WAKE} += $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}; 612 $perprocess{$process}->{MM_VMSCAN_WAKEUP_KSWAPD} += $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}; 613 $perprocess{$process}->{HIGH_KSWAPD_REWAKEUP} += $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP}; 614 $perprocess{$process}->{HIGH_NR_SCANNED} += $perprocesspid{$process_pid}->{HIGH_NR_SCANNED}; 615 $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}; 616 $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}; 617 $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}; 618 $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}; 619 620 for (my $order = 0; $order < 20; $order++) { 621 $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order]; 622 $perprocess{$process}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order]; 623 $perprocess{$process}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order]; 624 625 } 626 627 # Aggregate direct reclaim latencies 628 my $wr_index = $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END}; 629 my $rd_index = 0; 630 while (defined $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$rd_index]) { 631 $perprocess{$process}->{HIGH_DIRECT_RECLAIM_LATENCY}[$wr_index] = $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$rd_index]; 632 $rd_index++; 633 $wr_index++; 634 } 635 $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END} = $wr_index; 636 637 # Aggregate kswapd latencies 638 my $wr_index = $perprocess{$process}->{MM_VMSCAN_KSWAPD_SLEEP}; 639 my $rd_index = 0; 640 while (defined $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$rd_index]) { 641 $perprocess{$process}->{HIGH_KSWAPD_LATENCY}[$wr_index] = $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$rd_index]; 642 $rd_index++; 643 $wr_index++; 644 } 645 $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END} = $wr_index; 646 } 647} 648 649sub report() { 650 if (!$opt_ignorepid) { 651 dump_stats(\%perprocesspid); 652 } else { 653 aggregate_perprocesspid(); 654 dump_stats(\%perprocess); 655 } 656} 657 658# Process events or signals until neither is available 659sub signal_loop() { 660 my $sigint_processed; 661 do { 662 $sigint_processed = 0; 663 process_events(); 664 665 # Handle pending signals if any 666 if ($sigint_pending) { 667 my $current_time = time; 668 669 if ($sigint_exit) { 670 print "Received exit signal\n"; 671 $sigint_pending = 0; 672 } 673 if ($sigint_report) { 674 if ($current_time >= $sigint_received + 2) { 675 report(); 676 $sigint_report = 0; 677 $sigint_pending = 0; 678 $sigint_processed = 1; 679 } 680 } 681 } 682 } while ($sigint_pending || $sigint_processed); 683} 684 685signal_loop(); 686report(); 687