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