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