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 $isolate_mode = $1; 377 my $nr_scanned = $4; 378 my $nr_contig_dirty = $7; 379 380 # To closer match vmstat scanning statistics, only count isolate_both 381 # and isolate_inactive as scanning. isolate_active is rotation 382 # isolate_inactive == 1 383 # isolate_active == 2 384 # isolate_both == 3 385 if ($isolate_mode != 2) { 386 $perprocesspid{$process_pid}->{HIGH_NR_SCANNED} += $nr_scanned; 387 } 388 $perprocesspid{$process_pid}->{HIGH_NR_CONTIG_DIRTY} += $nr_contig_dirty; 389 } elsif ($tracepoint eq "mm_vmscan_lru_shrink_inactive") { 390 $details = $5; 391 if ($details !~ /$regex_lru_shrink_inactive/o) { 392 print "WARNING: Failed to parse mm_vmscan_lru_shrink_inactive as expected\n"; 393 print " $details\n"; 394 print " $regex_lru_shrink_inactive/o\n"; 395 next; 396 } 397 my $nr_reclaimed = $4; 398 $perprocesspid{$process_pid}->{HIGH_NR_RECLAIMED} += $nr_reclaimed; 399 } elsif ($tracepoint eq "mm_vmscan_writepage") { 400 $details = $5; 401 if ($details !~ /$regex_writepage/o) { 402 print "WARNING: Failed to parse mm_vmscan_writepage as expected\n"; 403 print " $details\n"; 404 print " $regex_writepage\n"; 405 next; 406 } 407 408 my $flags = $3; 409 my $file = 0; 410 my $sync_io = 0; 411 if ($flags =~ /RECLAIM_WB_FILE/) { 412 $file = 1; 413 } 414 if ($flags =~ /RECLAIM_WB_SYNC/) { 415 $sync_io = 1; 416 } 417 if ($sync_io) { 418 if ($file) { 419 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}++; 420 } else { 421 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}++; 422 } 423 } else { 424 if ($file) { 425 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}++; 426 } else { 427 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}++; 428 } 429 } 430 } else { 431 $perprocesspid{$process_pid}->{EVENT_UNKNOWN}++; 432 } 433 434 if ($sigint_pending) { 435 last EVENT_PROCESS; 436 } 437 } 438} 439 440sub dump_stats { 441 my $hashref = shift; 442 my %stats = %$hashref; 443 444 # Dump per-process stats 445 my $process_pid; 446 my $max_strlen = 0; 447 448 # Get the maximum process name 449 foreach $process_pid (keys %perprocesspid) { 450 my $len = length($process_pid); 451 if ($len > $max_strlen) { 452 $max_strlen = $len; 453 } 454 } 455 $max_strlen += 2; 456 457 # Work out latencies 458 printf("\n") if !$opt_ignorepid; 459 printf("Reclaim latencies expressed as order-latency_in_ms\n") if !$opt_ignorepid; 460 foreach $process_pid (keys %stats) { 461 462 if (!$stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[0] && 463 !$stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[0]) { 464 next; 465 } 466 467 printf "%-" . $max_strlen . "s ", $process_pid if !$opt_ignorepid; 468 my $index = 0; 469 while (defined $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index] || 470 defined $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]) { 471 472 if ($stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) { 473 printf("%s ", $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) if !$opt_ignorepid; 474 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]); 475 $total_direct_latency += $latency; 476 } else { 477 printf("%s ", $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]) if !$opt_ignorepid; 478 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]); 479 $total_kswapd_latency += $latency; 480 } 481 $index++; 482 } 483 print "\n" if !$opt_ignorepid; 484 } 485 486 # Print out process activity 487 printf("\n"); 488 printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s %8s %8s\n", "Process", "Direct", "Wokeup", "Pages", "Pages", "Pages", "Pages", "Time"); 489 printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s %8s %8s\n", "details", "Rclms", "Kswapd", "Scanned", "Rclmed", "Sync-IO", "ASync-IO", "Stalled"); 490 foreach $process_pid (keys %stats) { 491 492 if (!$stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}) { 493 next; 494 } 495 496 $total_direct_reclaim += $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}; 497 $total_wakeup_kswapd += $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}; 498 $total_direct_nr_scanned += $stats{$process_pid}->{HIGH_NR_SCANNED}; 499 $total_direct_nr_reclaimed += $stats{$process_pid}->{HIGH_NR_RECLAIMED}; 500 $total_direct_writepage_file_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}; 501 $total_direct_writepage_anon_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}; 502 $total_direct_writepage_file_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}; 503 504 $total_direct_writepage_anon_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}; 505 506 my $index = 0; 507 my $this_reclaim_delay = 0; 508 while (defined $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) { 509 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]); 510 $this_reclaim_delay += $latency; 511 $index++; 512 } 513 514 printf("%-" . $max_strlen . "s %8d %10d %8u %8u %8u %8u %8.3f", 515 $process_pid, 516 $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}, 517 $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}, 518 $stats{$process_pid}->{HIGH_NR_SCANNED}, 519 $stats{$process_pid}->{HIGH_NR_RECLAIMED}, 520 $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}, 521 $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}, 522 $this_reclaim_delay / 1000); 523 524 if ($stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}) { 525 print " "; 526 for (my $order = 0; $order < 20; $order++) { 527 my $count = $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order]; 528 if ($count != 0) { 529 print "direct-$order=$count "; 530 } 531 } 532 } 533 if ($stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}) { 534 print " "; 535 for (my $order = 0; $order < 20; $order++) { 536 my $count = $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order]; 537 if ($count != 0) { 538 print "wakeup-$order=$count "; 539 } 540 } 541 } 542 if ($stats{$process_pid}->{HIGH_NR_CONTIG_DIRTY}) { 543 print " "; 544 my $count = $stats{$process_pid}->{HIGH_NR_CONTIG_DIRTY}; 545 if ($count != 0) { 546 print "contig-dirty=$count "; 547 } 548 } 549 550 print "\n"; 551 } 552 553 # Print out kswapd activity 554 printf("\n"); 555 printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s\n", "Kswapd", "Kswapd", "Order", "Pages", "Pages", "Pages", "Pages"); 556 printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s\n", "Instance", "Wakeups", "Re-wakeup", "Scanned", "Rclmed", "Sync-IO", "ASync-IO"); 557 foreach $process_pid (keys %stats) { 558 559 if (!$stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}) { 560 next; 561 } 562 563 $total_kswapd_wake += $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}; 564 $total_kswapd_nr_scanned += $stats{$process_pid}->{HIGH_NR_SCANNED}; 565 $total_kswapd_nr_reclaimed += $stats{$process_pid}->{HIGH_NR_RECLAIMED}; 566 $total_kswapd_writepage_file_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}; 567 $total_kswapd_writepage_anon_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}; 568 $total_kswapd_writepage_file_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}; 569 $total_kswapd_writepage_anon_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}; 570 571 printf("%-" . $max_strlen . "s %8d %10d %8u %8u %8i %8u", 572 $process_pid, 573 $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}, 574 $stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP}, 575 $stats{$process_pid}->{HIGH_NR_SCANNED}, 576 $stats{$process_pid}->{HIGH_NR_RECLAIMED}, 577 $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}, 578 $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}); 579 580 if ($stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}) { 581 print " "; 582 for (my $order = 0; $order < 20; $order++) { 583 my $count = $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order]; 584 if ($count != 0) { 585 print "wake-$order=$count "; 586 } 587 } 588 } 589 if ($stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP}) { 590 print " "; 591 for (my $order = 0; $order < 20; $order++) { 592 my $count = $stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP_PERORDER}[$order]; 593 if ($count != 0) { 594 print "rewake-$order=$count "; 595 } 596 } 597 } 598 printf("\n"); 599 } 600 601 # Print out summaries 602 $total_direct_latency /= 1000; 603 $total_kswapd_latency /= 1000; 604 print "\nSummary\n"; 605 print "Direct reclaims: $total_direct_reclaim\n"; 606 print "Direct reclaim pages scanned: $total_direct_nr_scanned\n"; 607 print "Direct reclaim pages reclaimed: $total_direct_nr_reclaimed\n"; 608 print "Direct reclaim write file sync I/O: $total_direct_writepage_file_sync\n"; 609 print "Direct reclaim write anon sync I/O: $total_direct_writepage_anon_sync\n"; 610 print "Direct reclaim write file async I/O: $total_direct_writepage_file_async\n"; 611 print "Direct reclaim write anon async I/O: $total_direct_writepage_anon_async\n"; 612 print "Wake kswapd requests: $total_wakeup_kswapd\n"; 613 printf "Time stalled direct reclaim: %-1.2f seconds\n", $total_direct_latency; 614 print "\n"; 615 print "Kswapd wakeups: $total_kswapd_wake\n"; 616 print "Kswapd pages scanned: $total_kswapd_nr_scanned\n"; 617 print "Kswapd pages reclaimed: $total_kswapd_nr_reclaimed\n"; 618 print "Kswapd reclaim write file sync I/O: $total_kswapd_writepage_file_sync\n"; 619 print "Kswapd reclaim write anon sync I/O: $total_kswapd_writepage_anon_sync\n"; 620 print "Kswapd reclaim write file async I/O: $total_kswapd_writepage_file_async\n"; 621 print "Kswapd reclaim write anon async I/O: $total_kswapd_writepage_anon_async\n"; 622 printf "Time kswapd awake: %-1.2f seconds\n", $total_kswapd_latency; 623} 624 625sub aggregate_perprocesspid() { 626 my $process_pid; 627 my $process; 628 undef %perprocess; 629 630 foreach $process_pid (keys %perprocesspid) { 631 $process = $process_pid; 632 $process =~ s/-([0-9])*$//; 633 if ($process eq '') { 634 $process = "NO_PROCESS_NAME"; 635 } 636 637 $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN} += $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}; 638 $perprocess{$process}->{MM_VMSCAN_KSWAPD_WAKE} += $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}; 639 $perprocess{$process}->{MM_VMSCAN_WAKEUP_KSWAPD} += $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}; 640 $perprocess{$process}->{HIGH_KSWAPD_REWAKEUP} += $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP}; 641 $perprocess{$process}->{HIGH_NR_SCANNED} += $perprocesspid{$process_pid}->{HIGH_NR_SCANNED}; 642 $perprocess{$process}->{HIGH_NR_RECLAIMED} += $perprocesspid{$process_pid}->{HIGH_NR_RECLAIMED}; 643 $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}; 644 $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}; 645 $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}; 646 $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}; 647 648 for (my $order = 0; $order < 20; $order++) { 649 $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order]; 650 $perprocess{$process}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order]; 651 $perprocess{$process}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order]; 652 653 } 654 655 # Aggregate direct reclaim latencies 656 my $wr_index = $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END}; 657 my $rd_index = 0; 658 while (defined $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$rd_index]) { 659 $perprocess{$process}->{HIGH_DIRECT_RECLAIM_LATENCY}[$wr_index] = $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$rd_index]; 660 $rd_index++; 661 $wr_index++; 662 } 663 $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END} = $wr_index; 664 665 # Aggregate kswapd latencies 666 my $wr_index = $perprocess{$process}->{MM_VMSCAN_KSWAPD_SLEEP}; 667 my $rd_index = 0; 668 while (defined $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$rd_index]) { 669 $perprocess{$process}->{HIGH_KSWAPD_LATENCY}[$wr_index] = $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$rd_index]; 670 $rd_index++; 671 $wr_index++; 672 } 673 $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END} = $wr_index; 674 } 675} 676 677sub report() { 678 if (!$opt_ignorepid) { 679 dump_stats(\%perprocesspid); 680 } else { 681 aggregate_perprocesspid(); 682 dump_stats(\%perprocess); 683 } 684} 685 686# Process events or signals until neither is available 687sub signal_loop() { 688 my $sigint_processed; 689 do { 690 $sigint_processed = 0; 691 process_events(); 692 693 # Handle pending signals if any 694 if ($sigint_pending) { 695 my $current_time = time; 696 697 if ($sigint_exit) { 698 print "Received exit signal\n"; 699 $sigint_pending = 0; 700 } 701 if ($sigint_report) { 702 if ($current_time >= $sigint_received + 2) { 703 report(); 704 $sigint_report = 0; 705 $sigint_pending = 0; 706 $sigint_processed = 1; 707 } 708 } 709 } 710 } while ($sigint_pending || $sigint_processed); 711} 712 713signal_loop(); 714report(); 715