753 lines · plain
1#!/usr/bin/env perl2# This is a POC for reading the text representation of trace output related to3# page reclaim. It makes an attempt to extract some high-level information on4# what is going on. The accuracy of the parser may vary5#6# Example usage: trace-vmscan-postprocess.pl < /sys/kernel/tracing/trace_pipe7# other options8# --read-procstat If the trace lacks process info, get it from /proc9# --ignore-pid Aggregate processes of the same name together10#11# Copyright (c) IBM Corporation 200912# Author: Mel Gorman <mel@csn.ul.ie>13use strict;14use Getopt::Long;15 16# Tracepoint events17use 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 events32use 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 state38use 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 tracepoints44use 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 request77my $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 options104GetOptions(105 'ignore-pid' => \$opt_ignorepid,106 'read-procstat' => \$opt_read_procstat,107);108 109# Defaults for dynamically discovered regex's110my $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 regex121my $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 /o132# (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 default143 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 this163 # script, it really doesn't matter164 $regex =~ s/\(REC.*\) \? __print_flags.*//;165 166 # Verify fields are in the right order167 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 format258sub 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 log275EVENT_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 majorly303 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 itself320 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 time324 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 itself353 my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP};354 $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP}++;355 356 # Record how long kswapd was awake357 $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 count386 # inactive lru as scanning387 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 stats462 my $process_pid;463 my $max_strlen = 0;464 465 # Get the maximum process name466 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 latencies475 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 activity504 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 activity572 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 summaries628 $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 latencies694 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 latencies704 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 available725sub signal_loop() {726 my $sigint_processed;727 do {728 $sigint_processed = 0;729 process_events();730 731 # Handle pending signals if any732 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