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