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/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]*) 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]*) order=([0-9]*) gfp_flags=([A-Z_|]*)'; 115my $regex_lru_isolate_default = 'classzone=([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_taken=([0-9]*) nr_active=([0-9]*) nr_deactivated=([0-9]*) nr_referenced=([0-9]*) priority=([0-9]*) flags=([A-Z_|]*)' ; 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/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", "gfp_flags"); 188$regex_direct_end = generate_traceevent_regex( 189 "vmscan/mm_vmscan_direct_reclaim_end", 190 $regex_direct_end_default, 191 "nr_reclaimed"); 192$regex_kswapd_wake = generate_traceevent_regex( 193 "vmscan/mm_vmscan_kswapd_wake", 194 $regex_kswapd_wake_default, 195 "nid", "order"); 196$regex_kswapd_sleep = generate_traceevent_regex( 197 "vmscan/mm_vmscan_kswapd_sleep", 198 $regex_kswapd_sleep_default, 199 "nid"); 200$regex_wakeup_kswapd = generate_traceevent_regex( 201 "vmscan/mm_vmscan_wakeup_kswapd", 202 $regex_wakeup_kswapd_default, 203 "nid", "order", "gfp_flags"); 204$regex_lru_isolate = generate_traceevent_regex( 205 "vmscan/mm_vmscan_lru_isolate", 206 $regex_lru_isolate_default, 207 "classzone", "order", 208 "nr_requested", "nr_scanned", "nr_skipped", "nr_taken", 209 "lru"); 210$regex_lru_shrink_inactive = generate_traceevent_regex( 211 "vmscan/mm_vmscan_lru_shrink_inactive", 212 $regex_lru_shrink_inactive_default, 213 "nid", "nr_scanned", "nr_reclaimed", "nr_dirty", "nr_writeback", 214 "nr_congested", "nr_immediate", "nr_activate_anon", 215 "nr_activate_file", "nr_ref_keep", 216 "nr_unmap_fail", "priority", "flags"); 217$regex_lru_shrink_active = generate_traceevent_regex( 218 "vmscan/mm_vmscan_lru_shrink_active", 219 $regex_lru_shrink_active_default, 220 "nid", "nr_taken", "nr_active", "nr_deactivated", "nr_referenced", 221 "priority", "flags"); 222$regex_writepage = generate_traceevent_regex( 223 "vmscan/mm_vmscan_write_folio", 224 $regex_writepage_default, 225 "page", "pfn", "flags"); 226 227sub read_statline($) { 228 my $pid = $_[0]; 229 my $statline; 230 231 if (open(STAT, "/proc/$pid/stat")) { 232 $statline = <STAT>; 233 close(STAT); 234 } 235 236 if ($statline eq '') { 237 $statline = "-1 (UNKNOWN_PROCESS_NAME) R 0"; 238 } 239 240 return $statline; 241} 242 243sub guess_process_pid($$) { 244 my $pid = $_[0]; 245 my $statline = $_[1]; 246 247 if ($pid == 0) { 248 return "swapper-0"; 249 } 250 251 if ($statline !~ /$regex_statname/o) { 252 die("Failed to math stat line for process name :: $statline"); 253 } 254 return "$1-$pid"; 255} 256 257# Convert sec.usec timestamp format 258sub timestamp_to_ms($) { 259 my $timestamp = $_[0]; 260 261 my ($sec, $usec) = split (/\./, $timestamp); 262 return ($sec * 1000) + ($usec / 1000); 263} 264 265sub process_events { 266 my $traceevent; 267 my $process_pid; 268 my $cpus; 269 my $timestamp; 270 my $tracepoint; 271 my $details; 272 my $statline; 273 274 # Read each line of the event log 275EVENT_PROCESS: 276 while ($traceevent = <STDIN>) { 277 if ($traceevent =~ /$regex_traceevent/o) { 278 $process_pid = $1; 279 $timestamp = $4; 280 $tracepoint = $5; 281 282 $process_pid =~ /(.*)-([0-9]*)$/; 283 my $process = $1; 284 my $pid = $2; 285 286 if ($process eq "") { 287 $process = $last_procmap{$pid}; 288 $process_pid = "$process-$pid"; 289 } 290 $last_procmap{$pid} = $process; 291 292 if ($opt_read_procstat) { 293 $statline = read_statline($pid); 294 if ($opt_read_procstat && $process eq '') { 295 $process_pid = guess_process_pid($pid, $statline); 296 } 297 } 298 } else { 299 next; 300 } 301 302 # Perl Switch() sucks majorly 303 if ($tracepoint eq "mm_vmscan_direct_reclaim_begin") { 304 $timestamp = timestamp_to_ms($timestamp); 305 $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}++; 306 $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN} = $timestamp; 307 308 $details = $6; 309 if ($details !~ /$regex_direct_begin/o) { 310 print "WARNING: Failed to parse mm_vmscan_direct_reclaim_begin as expected\n"; 311 print " $details\n"; 312 print " $regex_direct_begin\n"; 313 next; 314 } 315 my $order = $1; 316 $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order]++; 317 $perprocesspid{$process_pid}->{STATE_DIRECT_ORDER} = $order; 318 } elsif ($tracepoint eq "mm_vmscan_direct_reclaim_end") { 319 # Count the event itself 320 my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_END}; 321 $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_END}++; 322 323 # Record how long direct reclaim took this time 324 if (defined $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN}) { 325 $timestamp = timestamp_to_ms($timestamp); 326 my $order = $perprocesspid{$process_pid}->{STATE_DIRECT_ORDER}; 327 my $latency = ($timestamp - $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN}); 328 $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index] = "$order-$latency"; 329 } 330 } elsif ($tracepoint eq "mm_vmscan_kswapd_wake") { 331 $details = $6; 332 if ($details !~ /$regex_kswapd_wake/o) { 333 print "WARNING: Failed to parse mm_vmscan_kswapd_wake as expected\n"; 334 print " $details\n"; 335 print " $regex_kswapd_wake\n"; 336 next; 337 } 338 339 my $order = $2; 340 $perprocesspid{$process_pid}->{STATE_KSWAPD_ORDER} = $order; 341 if (!$perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN}) { 342 $timestamp = timestamp_to_ms($timestamp); 343 $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}++; 344 $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN} = $timestamp; 345 $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order]++; 346 } else { 347 $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP}++; 348 $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP_PERORDER}[$order]++; 349 } 350 } elsif ($tracepoint eq "mm_vmscan_kswapd_sleep") { 351 352 # Count the event itself 353 my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP}; 354 $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP}++; 355 356 # Record how long kswapd was awake 357 $timestamp = timestamp_to_ms($timestamp); 358 my $order = $perprocesspid{$process_pid}->{STATE_KSWAPD_ORDER}; 359 my $latency = ($timestamp - $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN}); 360 $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index] = "$order-$latency"; 361 $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN} = 0; 362 } elsif ($tracepoint eq "mm_vmscan_wakeup_kswapd") { 363 $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}++; 364 365 $details = $6; 366 if ($details !~ /$regex_wakeup_kswapd/o) { 367 print "WARNING: Failed to parse mm_vmscan_wakeup_kswapd as expected\n"; 368 print " $details\n"; 369 print " $regex_wakeup_kswapd\n"; 370 next; 371 } 372 my $order = $2; 373 $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order]++; 374 } elsif ($tracepoint eq "mm_vmscan_lru_isolate") { 375 $details = $6; 376 if ($details !~ /$regex_lru_isolate/o) { 377 print "WARNING: Failed to parse mm_vmscan_lru_isolate as expected\n"; 378 print " $details\n"; 379 print " $regex_lru_isolate/o\n"; 380 next; 381 } 382 my $nr_scanned = $4; 383 my $lru = $7; 384 385 # To closer match vmstat scanning statistics, only count 386 # inactive lru as scanning 387 if ($lru =~ /inactive_/) { 388 $perprocesspid{$process_pid}->{HIGH_NR_SCANNED} += $nr_scanned; 389 if ($lru =~ /_file/) { 390 $perprocesspid{$process_pid}->{HIGH_NR_FILE_SCANNED} += $nr_scanned; 391 } else { 392 $perprocesspid{$process_pid}->{HIGH_NR_ANON_SCANNED} += $nr_scanned; 393 } 394 } 395 } elsif ($tracepoint eq "mm_vmscan_lru_shrink_inactive") { 396 $details = $6; 397 if ($details !~ /$regex_lru_shrink_inactive/o) { 398 print "WARNING: Failed to parse mm_vmscan_lru_shrink_inactive as expected\n"; 399 print " $details\n"; 400 print " $regex_lru_shrink_inactive/o\n"; 401 next; 402 } 403 404 my $nr_reclaimed = $3; 405 my $flags = $13; 406 my $file = 0; 407 if ($flags =~ /RECLAIM_WB_FILE/) { 408 $file = 1; 409 } 410 $perprocesspid{$process_pid}->{HIGH_NR_RECLAIMED} += $nr_reclaimed; 411 if ($file) { 412 $perprocesspid{$process_pid}->{HIGH_NR_FILE_RECLAIMED} += $nr_reclaimed; 413 } else { 414 $perprocesspid{$process_pid}->{HIGH_NR_ANON_RECLAIMED} += $nr_reclaimed; 415 } 416 } elsif ($tracepoint eq "mm_vmscan_writepage") { 417 $details = $6; 418 if ($details !~ /$regex_writepage/o) { 419 print "WARNING: Failed to parse mm_vmscan_writepage as expected\n"; 420 print " $details\n"; 421 print " $regex_writepage\n"; 422 next; 423 } 424 425 my $flags = $3; 426 my $file = 0; 427 my $sync_io = 0; 428 if ($flags =~ /RECLAIM_WB_FILE/) { 429 $file = 1; 430 } 431 if ($flags =~ /RECLAIM_WB_SYNC/) { 432 $sync_io = 1; 433 } 434 if ($sync_io) { 435 if ($file) { 436 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}++; 437 } else { 438 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}++; 439 } 440 } else { 441 if ($file) { 442 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}++; 443 } else { 444 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}++; 445 } 446 } 447 } else { 448 $perprocesspid{$process_pid}->{EVENT_UNKNOWN}++; 449 } 450 451 if ($sigint_pending) { 452 last EVENT_PROCESS; 453 } 454 } 455} 456 457sub dump_stats { 458 my $hashref = shift; 459 my %stats = %$hashref; 460 461 # Dump per-process stats 462 my $process_pid; 463 my $max_strlen = 0; 464 465 # Get the maximum process name 466 foreach $process_pid (keys %perprocesspid) { 467 my $len = length($process_pid); 468 if ($len > $max_strlen) { 469 $max_strlen = $len; 470 } 471 } 472 $max_strlen += 2; 473 474 # Work out latencies 475 printf("\n") if !$opt_ignorepid; 476 printf("Reclaim latencies expressed as order-latency_in_ms\n") if !$opt_ignorepid; 477 foreach $process_pid (keys %stats) { 478 479 if (!$stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[0] && 480 !$stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[0]) { 481 next; 482 } 483 484 printf "%-" . $max_strlen . "s ", $process_pid if !$opt_ignorepid; 485 my $index = 0; 486 while (defined $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index] || 487 defined $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]) { 488 489 if ($stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) { 490 printf("%s ", $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) if !$opt_ignorepid; 491 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]); 492 $total_direct_latency += $latency; 493 } else { 494 printf("%s ", $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]) if !$opt_ignorepid; 495 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]); 496 $total_kswapd_latency += $latency; 497 } 498 $index++; 499 } 500 print "\n" if !$opt_ignorepid; 501 } 502 503 # Print out process activity 504 printf("\n"); 505 printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s %8s %8s\n", "Process", "Direct", "Wokeup", "Pages", "Pages", "Pages", "Pages", "Time"); 506 printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s %8s %8s\n", "details", "Rclms", "Kswapd", "Scanned", "Rclmed", "Sync-IO", "ASync-IO", "Stalled"); 507 foreach $process_pid (keys %stats) { 508 509 if (!$stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}) { 510 next; 511 } 512 513 $total_direct_reclaim += $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}; 514 $total_wakeup_kswapd += $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}; 515 $total_direct_nr_scanned += $stats{$process_pid}->{HIGH_NR_SCANNED}; 516 $total_direct_nr_file_scanned += $stats{$process_pid}->{HIGH_NR_FILE_SCANNED}; 517 $total_direct_nr_anon_scanned += $stats{$process_pid}->{HIGH_NR_ANON_SCANNED}; 518 $total_direct_nr_reclaimed += $stats{$process_pid}->{HIGH_NR_RECLAIMED}; 519 $total_direct_nr_file_reclaimed += $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED}; 520 $total_direct_nr_anon_reclaimed += $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED}; 521 $total_direct_writepage_file_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}; 522 $total_direct_writepage_anon_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}; 523 $total_direct_writepage_file_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}; 524 525 $total_direct_writepage_anon_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}; 526 527 my $index = 0; 528 my $this_reclaim_delay = 0; 529 while (defined $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) { 530 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]); 531 $this_reclaim_delay += $latency; 532 $index++; 533 } 534 535 printf("%-" . $max_strlen . "s %8d %10d %8u %8u %8u %8u %8.3f", 536 $process_pid, 537 $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}, 538 $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}, 539 $stats{$process_pid}->{HIGH_NR_SCANNED}, 540 $stats{$process_pid}->{HIGH_NR_FILE_SCANNED}, 541 $stats{$process_pid}->{HIGH_NR_ANON_SCANNED}, 542 $stats{$process_pid}->{HIGH_NR_RECLAIMED}, 543 $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED}, 544 $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED}, 545 $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}, 546 $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}, 547 $this_reclaim_delay / 1000); 548 549 if ($stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}) { 550 print " "; 551 for (my $order = 0; $order < 20; $order++) { 552 my $count = $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order]; 553 if ($count != 0) { 554 print "direct-$order=$count "; 555 } 556 } 557 } 558 if ($stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}) { 559 print " "; 560 for (my $order = 0; $order < 20; $order++) { 561 my $count = $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order]; 562 if ($count != 0) { 563 print "wakeup-$order=$count "; 564 } 565 } 566 } 567 568 print "\n"; 569 } 570 571 # Print out kswapd activity 572 printf("\n"); 573 printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s\n", "Kswapd", "Kswapd", "Order", "Pages", "Pages", "Pages", "Pages"); 574 printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s\n", "Instance", "Wakeups", "Re-wakeup", "Scanned", "Rclmed", "Sync-IO", "ASync-IO"); 575 foreach $process_pid (keys %stats) { 576 577 if (!$stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}) { 578 next; 579 } 580 581 $total_kswapd_wake += $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}; 582 $total_kswapd_nr_scanned += $stats{$process_pid}->{HIGH_NR_SCANNED}; 583 $total_kswapd_nr_file_scanned += $stats{$process_pid}->{HIGH_NR_FILE_SCANNED}; 584 $total_kswapd_nr_anon_scanned += $stats{$process_pid}->{HIGH_NR_ANON_SCANNED}; 585 $total_kswapd_nr_reclaimed += $stats{$process_pid}->{HIGH_NR_RECLAIMED}; 586 $total_kswapd_nr_file_reclaimed += $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED}; 587 $total_kswapd_nr_anon_reclaimed += $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED}; 588 $total_kswapd_writepage_file_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}; 589 $total_kswapd_writepage_anon_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}; 590 $total_kswapd_writepage_file_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}; 591 $total_kswapd_writepage_anon_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}; 592 593 printf("%-" . $max_strlen . "s %8d %10d %8u %8u %8i %8u", 594 $process_pid, 595 $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}, 596 $stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP}, 597 $stats{$process_pid}->{HIGH_NR_SCANNED}, 598 $stats{$process_pid}->{HIGH_NR_FILE_SCANNED}, 599 $stats{$process_pid}->{HIGH_NR_ANON_SCANNED}, 600 $stats{$process_pid}->{HIGH_NR_RECLAIMED}, 601 $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED}, 602 $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED}, 603 $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}, 604 $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}); 605 606 if ($stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}) { 607 print " "; 608 for (my $order = 0; $order < 20; $order++) { 609 my $count = $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order]; 610 if ($count != 0) { 611 print "wake-$order=$count "; 612 } 613 } 614 } 615 if ($stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP}) { 616 print " "; 617 for (my $order = 0; $order < 20; $order++) { 618 my $count = $stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP_PERORDER}[$order]; 619 if ($count != 0) { 620 print "rewake-$order=$count "; 621 } 622 } 623 } 624 printf("\n"); 625 } 626 627 # Print out summaries 628 $total_direct_latency /= 1000; 629 $total_kswapd_latency /= 1000; 630 print "\nSummary\n"; 631 print "Direct reclaims: $total_direct_reclaim\n"; 632 print "Direct reclaim pages scanned: $total_direct_nr_scanned\n"; 633 print "Direct reclaim file pages scanned: $total_direct_nr_file_scanned\n"; 634 print "Direct reclaim anon pages scanned: $total_direct_nr_anon_scanned\n"; 635 print "Direct reclaim pages reclaimed: $total_direct_nr_reclaimed\n"; 636 print "Direct reclaim file pages reclaimed: $total_direct_nr_file_reclaimed\n"; 637 print "Direct reclaim anon pages reclaimed: $total_direct_nr_anon_reclaimed\n"; 638 print "Direct reclaim write file sync I/O: $total_direct_writepage_file_sync\n"; 639 print "Direct reclaim write anon sync I/O: $total_direct_writepage_anon_sync\n"; 640 print "Direct reclaim write file async I/O: $total_direct_writepage_file_async\n"; 641 print "Direct reclaim write anon async I/O: $total_direct_writepage_anon_async\n"; 642 print "Wake kswapd requests: $total_wakeup_kswapd\n"; 643 printf "Time stalled direct reclaim: %-1.2f seconds\n", $total_direct_latency; 644 print "\n"; 645 print "Kswapd wakeups: $total_kswapd_wake\n"; 646 print "Kswapd pages scanned: $total_kswapd_nr_scanned\n"; 647 print "Kswapd file pages scanned: $total_kswapd_nr_file_scanned\n"; 648 print "Kswapd anon pages scanned: $total_kswapd_nr_anon_scanned\n"; 649 print "Kswapd pages reclaimed: $total_kswapd_nr_reclaimed\n"; 650 print "Kswapd file pages reclaimed: $total_kswapd_nr_file_reclaimed\n"; 651 print "Kswapd anon pages reclaimed: $total_kswapd_nr_anon_reclaimed\n"; 652 print "Kswapd reclaim write file sync I/O: $total_kswapd_writepage_file_sync\n"; 653 print "Kswapd reclaim write anon sync I/O: $total_kswapd_writepage_anon_sync\n"; 654 print "Kswapd reclaim write file async I/O: $total_kswapd_writepage_file_async\n"; 655 print "Kswapd reclaim write anon async I/O: $total_kswapd_writepage_anon_async\n"; 656 printf "Time kswapd awake: %-1.2f seconds\n", $total_kswapd_latency; 657} 658 659sub aggregate_perprocesspid() { 660 my $process_pid; 661 my $process; 662 undef %perprocess; 663 664 foreach $process_pid (keys %perprocesspid) { 665 $process = $process_pid; 666 $process =~ s/-([0-9])*$//; 667 if ($process eq '') { 668 $process = "NO_PROCESS_NAME"; 669 } 670 671 $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN} += $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}; 672 $perprocess{$process}->{MM_VMSCAN_KSWAPD_WAKE} += $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}; 673 $perprocess{$process}->{MM_VMSCAN_WAKEUP_KSWAPD} += $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}; 674 $perprocess{$process}->{HIGH_KSWAPD_REWAKEUP} += $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP}; 675 $perprocess{$process}->{HIGH_NR_SCANNED} += $perprocesspid{$process_pid}->{HIGH_NR_SCANNED}; 676 $perprocess{$process}->{HIGH_NR_FILE_SCANNED} += $perprocesspid{$process_pid}->{HIGH_NR_FILE_SCANNED}; 677 $perprocess{$process}->{HIGH_NR_ANON_SCANNED} += $perprocesspid{$process_pid}->{HIGH_NR_ANON_SCANNED}; 678 $perprocess{$process}->{HIGH_NR_RECLAIMED} += $perprocesspid{$process_pid}->{HIGH_NR_RECLAIMED}; 679 $perprocess{$process}->{HIGH_NR_FILE_RECLAIMED} += $perprocesspid{$process_pid}->{HIGH_NR_FILE_RECLAIMED}; 680 $perprocess{$process}->{HIGH_NR_ANON_RECLAIMED} += $perprocesspid{$process_pid}->{HIGH_NR_ANON_RECLAIMED}; 681 $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}; 682 $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}; 683 $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}; 684 $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}; 685 686 for (my $order = 0; $order < 20; $order++) { 687 $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order]; 688 $perprocess{$process}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order]; 689 $perprocess{$process}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order]; 690 691 } 692 693 # Aggregate direct reclaim latencies 694 my $wr_index = $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END}; 695 my $rd_index = 0; 696 while (defined $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$rd_index]) { 697 $perprocess{$process}->{HIGH_DIRECT_RECLAIM_LATENCY}[$wr_index] = $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$rd_index]; 698 $rd_index++; 699 $wr_index++; 700 } 701 $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END} = $wr_index; 702 703 # Aggregate kswapd latencies 704 my $wr_index = $perprocess{$process}->{MM_VMSCAN_KSWAPD_SLEEP}; 705 my $rd_index = 0; 706 while (defined $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$rd_index]) { 707 $perprocess{$process}->{HIGH_KSWAPD_LATENCY}[$wr_index] = $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$rd_index]; 708 $rd_index++; 709 $wr_index++; 710 } 711 $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END} = $wr_index; 712 } 713} 714 715sub report() { 716 if (!$opt_ignorepid) { 717 dump_stats(\%perprocesspid); 718 } else { 719 aggregate_perprocesspid(); 720 dump_stats(\%perprocess); 721 } 722} 723 724# Process events or signals until neither is available 725sub signal_loop() { 726 my $sigint_processed; 727 do { 728 $sigint_processed = 0; 729 process_events(); 730 731 # Handle pending signals if any 732 if ($sigint_pending) { 733 my $current_time = time; 734 735 if ($sigint_exit) { 736 print "Received exit signal\n"; 737 $sigint_pending = 0; 738 } 739 if ($sigint_report) { 740 if ($current_time >= $sigint_received + 2) { 741 report(); 742 $sigint_report = 0; 743 $sigint_pending = 0; 744 $sigint_processed = 1; 745 } 746 } 747 } 748 } while ($sigint_pending || $sigint_processed); 749} 750 751signal_loop(); 752report(); 753