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