trace/postprocess/trace-vmscan-postprocess.pl

0001 #!/usr/bin/env perl
0002 # This is a POC for reading the text representation of trace output related to
0003 # page reclaim. It makes an attempt to extract some high-level information on
0004 # what is going on. The accuracy of the parser may vary
0005 #
0006 # Example usage: trace-vmscan-postprocess.pl < /sys/kernel/debug/tracing/trace_pipe
0007 # other options
0008 #   --read-procstat If the trace lacks process info, get it from /proc
0009 #   --ignore-pid    Aggregate processes of the same name together
0010 #
0011 # Copyright (c) IBM Corporation 2009
0012 # Author: Mel Gorman <mel@csn.ul.ie>
0013 use strict;
0014 use Getopt::Long;
0015
0016 # Tracepoint events
0017 use constant MM_VMSCAN_DIRECT_RECLAIM_BEGIN => 1;
0018 use constant MM_VMSCAN_DIRECT_RECLAIM_END   => 2;
0019 use constant MM_VMSCAN_KSWAPD_WAKE      => 3;
0020 use constant MM_VMSCAN_KSWAPD_SLEEP     => 4;
0021 use constant MM_VMSCAN_LRU_SHRINK_ACTIVE    => 5;
0022 use constant MM_VMSCAN_LRU_SHRINK_INACTIVE  => 6;
0023 use constant MM_VMSCAN_LRU_ISOLATE      => 7;
0024 use constant MM_VMSCAN_WRITEPAGE_FILE_SYNC  => 8;
0025 use constant MM_VMSCAN_WRITEPAGE_ANON_SYNC  => 9;
0026 use constant MM_VMSCAN_WRITEPAGE_FILE_ASYNC => 10;
0027 use constant MM_VMSCAN_WRITEPAGE_ANON_ASYNC => 11;
0028 use constant MM_VMSCAN_WRITEPAGE_ASYNC      => 12;
0029 use constant EVENT_UNKNOWN          => 13;
0030
0031 # Per-order events
0032 use constant MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER => 11;
0033 use constant MM_VMSCAN_WAKEUP_KSWAPD_PERORDER   => 12;
0034 use constant MM_VMSCAN_KSWAPD_WAKE_PERORDER => 13;
0035 use constant HIGH_KSWAPD_REWAKEUP_PERORDER  => 14;
0036
0037 # Constants used to track state
0038 use constant STATE_DIRECT_BEGIN         => 15;
0039 use constant STATE_DIRECT_ORDER         => 16;
0040 use constant STATE_KSWAPD_BEGIN         => 17;
0041 use constant STATE_KSWAPD_ORDER         => 18;
0042
0043 # High-level events extrapolated from tracepoints
0044 use constant HIGH_DIRECT_RECLAIM_LATENCY    => 19;
0045 use constant HIGH_KSWAPD_LATENCY        => 20;
0046 use constant HIGH_KSWAPD_REWAKEUP       => 21;
0047 use constant HIGH_NR_SCANNED            => 22;
0048 use constant HIGH_NR_TAKEN          => 23;
0049 use constant HIGH_NR_RECLAIMED          => 24;
0050 use constant HIGH_NR_FILE_SCANNED       => 25;
0051 use constant HIGH_NR_ANON_SCANNED       => 26;
0052 use constant HIGH_NR_FILE_RECLAIMED     => 27;
0053 use constant HIGH_NR_ANON_RECLAIMED     => 28;
0054
0055 my %perprocesspid;
0056 my %perprocess;
0057 my %last_procmap;
0058 my $opt_ignorepid;
0059 my $opt_read_procstat;
0060
0061 my $total_wakeup_kswapd;
0062 my ($total_direct_reclaim, $total_direct_nr_scanned);
0063 my ($total_direct_nr_file_scanned, $total_direct_nr_anon_scanned);
0064 my ($total_direct_latency, $total_kswapd_latency);
0065 my ($total_direct_nr_reclaimed);
0066 my ($total_direct_nr_file_reclaimed, $total_direct_nr_anon_reclaimed);
0067 my ($total_direct_writepage_file_sync, $total_direct_writepage_file_async);
0068 my ($total_direct_writepage_anon_sync, $total_direct_writepage_anon_async);
0069 my ($total_kswapd_nr_scanned, $total_kswapd_wake);
0070 my ($total_kswapd_nr_file_scanned, $total_kswapd_nr_anon_scanned);
0071 my ($total_kswapd_writepage_file_sync, $total_kswapd_writepage_file_async);
0072 my ($total_kswapd_writepage_anon_sync, $total_kswapd_writepage_anon_async);
0073 my ($total_kswapd_nr_reclaimed);
0074 my ($total_kswapd_nr_file_reclaimed, $total_kswapd_nr_anon_reclaimed);
0075
0076 # Catch sigint and exit on request
0077 my $sigint_report = 0;
0078 my $sigint_exit = 0;
0079 my $sigint_pending = 0;
0080 my $sigint_received = 0;
0081 sub sigint_handler {
0082     my $current_time = time;
0083     if ($current_time - 2 > $sigint_received) {
0084         print "SIGINT received, report pending. Hit ctrl-c again to exit\n";
0085         $sigint_report = 1;
0086     } else {
0087         if (!$sigint_exit) {
0088             print "Second SIGINT received quickly, exiting\n";
0089         }
0090         $sigint_exit++;
0091     }
0092
0093     if ($sigint_exit > 3) {
0094         print "Many SIGINTs received, exiting now without report\n";
0095         exit;
0096     }
0097
0098     $sigint_received = $current_time;
0099     $sigint_pending = 1;
0100 }
0101 $SIG{INT} = "sigint_handler";
0102
0103 # Parse command line options
0104 GetOptions(
0105     'ignore-pid'     => \$opt_ignorepid,
0106     'read-procstat'  => \$opt_read_procstat,
0107 );
0108
0109 # Defaults for dynamically discovered regex's
0110 my $regex_direct_begin_default = 'order=([0-9]*) may_writepage=([0-9]*) gfp_flags=([A-Z_|]*)';
0111 my $regex_direct_end_default = 'nr_reclaimed=([0-9]*)';
0112 my $regex_kswapd_wake_default = 'nid=([0-9]*) order=([0-9]*)';
0113 my $regex_kswapd_sleep_default = 'nid=([0-9]*)';
0114 my $regex_wakeup_kswapd_default = 'nid=([0-9]*) zid=([0-9]*) order=([0-9]*) gfp_flags=([A-Z_|]*)';
0115 my $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_]*)';
0116 my $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_|]*)';
0117 my $regex_lru_shrink_active_default = 'lru=([A-Z_]*) nr_scanned=([0-9]*) nr_rotated=([0-9]*) priority=([0-9]*)';
0118 my $regex_writepage_default = 'page=([0-9a-f]*) pfn=([0-9]*) flags=([A-Z_|]*)';
0119
0120 # Dyanically discovered regex
0121 my $regex_direct_begin;
0122 my $regex_direct_end;
0123 my $regex_kswapd_wake;
0124 my $regex_kswapd_sleep;
0125 my $regex_wakeup_kswapd;
0126 my $regex_lru_isolate;
0127 my $regex_lru_shrink_inactive;
0128 my $regex_lru_shrink_active;
0129 my $regex_writepage;
0130
0131 # Static regex used. Specified like this for readability and for use with /o
0132 #                      (process_pid)     (cpus      )   ( time  )   (tpoint    ) (details)
0133 my $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*(.*)';
0134 my $regex_statname = '[-0-9]*\s\((.*)\).*';
0135 my $regex_statppid = '[-0-9]*\s\(.*\)\s[A-Za-z]\s([0-9]*).*';
0136
0137 sub generate_traceevent_regex {
0138     my $event = shift;
0139     my $default = shift;
0140     my $regex;
0141
0142     # Read the event format or use the default
0143     if (!open (FORMAT, "/sys/kernel/debug/tracing/events/$event/format")) {
0144         print("WARNING: Event $event format string not found\n");
0145         return $default;
0146     } else {
0147         my $line;
0148         while (!eof(FORMAT)) {
0149             $line = <FORMAT>;
0150             $line =~ s/, REC->.*//;
0151             if ($line =~ /^print fmt:\s"(.*)".*/) {
0152                 $regex = $1;
0153                 $regex =~ s/%s/\([0-9a-zA-Z|_]*\)/g;
0154                 $regex =~ s/%p/\([0-9a-f]*\)/g;
0155                 $regex =~ s/%d/\([-0-9]*\)/g;
0156                 $regex =~ s/%ld/\([-0-9]*\)/g;
0157                 $regex =~ s/%lu/\([0-9]*\)/g;
0158             }
0159         }
0160     }
0161
0162     # Can't handle the print_flags stuff but in the context of this
0163     # script, it really doesn't matter
0164     $regex =~ s/\(REC.*\) \? __print_flags.*//;
0165
0166     # Verify fields are in the right order
0167     my $tuple;
0168     foreach $tuple (split /\s/, $regex) {
0169         my ($key, $value) = split(/=/, $tuple);
0170         my $expected = shift;
0171         if ($key ne $expected) {
0172             print("WARNING: Format not as expected for event $event '$key' != '$expected'\n");
0173             $regex =~ s/$key=\((.*)\)/$key=$1/;
0174         }
0175     }
0176
0177     if (defined shift) {
0178         die("Fewer fields than expected in format");
0179     }
0180
0181     return $regex;
0182 }
0183
0184 $regex_direct_begin = generate_traceevent_regex(
0185             "vmscan/mm_vmscan_direct_reclaim_begin",
0186             $regex_direct_begin_default,
0187             "order", "may_writepage",
0188             "gfp_flags");
0189 $regex_direct_end = generate_traceevent_regex(
0190             "vmscan/mm_vmscan_direct_reclaim_end",
0191             $regex_direct_end_default,
0192             "nr_reclaimed");
0193 $regex_kswapd_wake = generate_traceevent_regex(
0194             "vmscan/mm_vmscan_kswapd_wake",
0195             $regex_kswapd_wake_default,
0196             "nid", "order");
0197 $regex_kswapd_sleep = generate_traceevent_regex(
0198             "vmscan/mm_vmscan_kswapd_sleep",
0199             $regex_kswapd_sleep_default,
0200             "nid");
0201 $regex_wakeup_kswapd = generate_traceevent_regex(
0202             "vmscan/mm_vmscan_wakeup_kswapd",
0203             $regex_wakeup_kswapd_default,
0204             "nid", "zid", "order", "gfp_flags");
0205 $regex_lru_isolate = generate_traceevent_regex(
0206             "vmscan/mm_vmscan_lru_isolate",
0207             $regex_lru_isolate_default,
0208             "isolate_mode", "classzone_idx", "order",
0209             "nr_requested", "nr_scanned", "nr_skipped", "nr_taken",
0210             "lru");
0211 $regex_lru_shrink_inactive = generate_traceevent_regex(
0212             "vmscan/mm_vmscan_lru_shrink_inactive",
0213             $regex_lru_shrink_inactive_default,
0214             "nid", "nr_scanned", "nr_reclaimed", "nr_dirty", "nr_writeback",
0215             "nr_congested", "nr_immediate", "nr_activate_anon",
0216             "nr_activate_file", "nr_ref_keep",
0217             "nr_unmap_fail", "priority", "flags");
0218 $regex_lru_shrink_active = generate_traceevent_regex(
0219             "vmscan/mm_vmscan_lru_shrink_active",
0220             $regex_lru_shrink_active_default,
0221             "nid", "zid",
0222             "lru",
0223             "nr_scanned", "nr_rotated", "priority");
0224 $regex_writepage = generate_traceevent_regex(
0225             "vmscan/mm_vmscan_writepage",
0226             $regex_writepage_default,
0227             "page", "pfn", "flags");
0228
0229 sub read_statline($) {
0230     my $pid = $_[0];
0231     my $statline;
0232
0233     if (open(STAT, "/proc/$pid/stat")) {
0234         $statline = <STAT>;
0235         close(STAT);
0236     }
0237
0238     if ($statline eq '') {
0239         $statline = "-1 (UNKNOWN_PROCESS_NAME) R 0";
0240     }
0241
0242     return $statline;
0243 }
0244
0245 sub guess_process_pid($$) {
0246     my $pid = $_[0];
0247     my $statline = $_[1];
0248
0249     if ($pid == 0) {
0250         return "swapper-0";
0251     }
0252
0253     if ($statline !~ /$regex_statname/o) {
0254         die("Failed to math stat line for process name :: $statline");
0255     }
0256     return "$1-$pid";
0257 }
0258
0259 # Convert sec.usec timestamp format
0260 sub timestamp_to_ms($) {
0261     my $timestamp = $_[0];
0262
0263     my ($sec, $usec) = split (/\./, $timestamp);
0264     return ($sec * 1000) + ($usec / 1000);
0265 }
0266
0267 sub process_events {
0268     my $traceevent;
0269     my $process_pid;
0270     my $cpus;
0271     my $timestamp;
0272     my $tracepoint;
0273     my $details;
0274     my $statline;
0275
0276     # Read each line of the event log
0277 EVENT_PROCESS:
0278     while ($traceevent = <STDIN>) {
0279         if ($traceevent =~ /$regex_traceevent/o) {
0280             $process_pid = $1;
0281             $timestamp = $4;
0282             $tracepoint = $5;
0283
0284             $process_pid =~ /(.*)-([0-9]*)$/;
0285             my $process = $1;
0286             my $pid = $2;
0287
0288             if ($process eq "") {
0289                 $process = $last_procmap{$pid};
0290                 $process_pid = "$process-$pid";
0291             }
0292             $last_procmap{$pid} = $process;
0293
0294             if ($opt_read_procstat) {
0295                 $statline = read_statline($pid);
0296                 if ($opt_read_procstat && $process eq '') {
0297                     $process_pid = guess_process_pid($pid, $statline);
0298                 }
0299             }
0300         } else {
0301             next;
0302         }
0303
0304         # Perl Switch() sucks majorly
0305         if ($tracepoint eq "mm_vmscan_direct_reclaim_begin") {
0306             $timestamp = timestamp_to_ms($timestamp);
0307             $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}++;
0308             $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN} = $timestamp;
0309
0310             $details = $6;
0311             if ($details !~ /$regex_direct_begin/o) {
0312                 print "WARNING: Failed to parse mm_vmscan_direct_reclaim_begin as expected\n";
0313                 print "         $details\n";
0314                 print "         $regex_direct_begin\n";
0315                 next;
0316             }
0317             my $order = $1;
0318             $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order]++;
0319             $perprocesspid{$process_pid}->{STATE_DIRECT_ORDER} = $order;
0320         } elsif ($tracepoint eq "mm_vmscan_direct_reclaim_end") {
0321             # Count the event itself
0322             my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_END};
0323             $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_END}++;
0324
0325             # Record how long direct reclaim took this time
0326             if (defined $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN}) {
0327                 $timestamp = timestamp_to_ms($timestamp);
0328                 my $order = $perprocesspid{$process_pid}->{STATE_DIRECT_ORDER};
0329                 my $latency = ($timestamp - $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN});
0330                 $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index] = "$order-$latency";
0331             }
0332         } elsif ($tracepoint eq "mm_vmscan_kswapd_wake") {
0333             $details = $6;
0334             if ($details !~ /$regex_kswapd_wake/o) {
0335                 print "WARNING: Failed to parse mm_vmscan_kswapd_wake as expected\n";
0336                 print "         $details\n";
0337                 print "         $regex_kswapd_wake\n";
0338                 next;
0339             }
0340
0341             my $order = $2;
0342             $perprocesspid{$process_pid}->{STATE_KSWAPD_ORDER} = $order;
0343             if (!$perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN}) {
0344                 $timestamp = timestamp_to_ms($timestamp);
0345                 $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}++;
0346                 $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN} = $timestamp;
0347                 $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order]++;
0348             } else {
0349                 $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP}++;
0350                 $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP_PERORDER}[$order]++;
0351             }
0352         } elsif ($tracepoint eq "mm_vmscan_kswapd_sleep") {
0353
0354             # Count the event itself
0355             my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP};
0356             $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP}++;
0357
0358             # Record how long kswapd was awake
0359             $timestamp = timestamp_to_ms($timestamp);
0360             my $order = $perprocesspid{$process_pid}->{STATE_KSWAPD_ORDER};
0361             my $latency = ($timestamp - $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN});
0362             $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index] = "$order-$latency";
0363             $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN} = 0;
0364         } elsif ($tracepoint eq "mm_vmscan_wakeup_kswapd") {
0365             $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}++;
0366
0367             $details = $6;
0368             if ($details !~ /$regex_wakeup_kswapd/o) {
0369                 print "WARNING: Failed to parse mm_vmscan_wakeup_kswapd as expected\n";
0370                 print "         $details\n";
0371                 print "         $regex_wakeup_kswapd\n";
0372                 next;
0373             }
0374             my $order = $3;
0375             $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order]++;
0376         } elsif ($tracepoint eq "mm_vmscan_lru_isolate") {
0377             $details = $6;
0378             if ($details !~ /$regex_lru_isolate/o) {
0379                 print "WARNING: Failed to parse mm_vmscan_lru_isolate as expected\n";
0380                 print "         $details\n";
0381                 print "         $regex_lru_isolate/o\n";
0382                 next;
0383             }
0384             my $isolate_mode = $1;
0385             my $nr_scanned = $5;
0386             my $file = $8;
0387
0388             # To closer match vmstat scanning statistics, only count isolate_both
0389             # and isolate_inactive as scanning. isolate_active is rotation
0390             # isolate_inactive == 1
0391             # isolate_active   == 2
0392             # isolate_both     == 3
0393             if ($isolate_mode != 2) {
0394                 $perprocesspid{$process_pid}->{HIGH_NR_SCANNED} += $nr_scanned;
0395                 if ($file =~ /_file/) {
0396                     $perprocesspid{$process_pid}->{HIGH_NR_FILE_SCANNED} += $nr_scanned;
0397                 } else {
0398                     $perprocesspid{$process_pid}->{HIGH_NR_ANON_SCANNED} += $nr_scanned;
0399                 }
0400             }
0401         } elsif ($tracepoint eq "mm_vmscan_lru_shrink_inactive") {
0402             $details = $6;
0403             if ($details !~ /$regex_lru_shrink_inactive/o) {
0404                 print "WARNING: Failed to parse mm_vmscan_lru_shrink_inactive as expected\n";
0405                 print "         $details\n";
0406                 print "         $regex_lru_shrink_inactive/o\n";
0407                 next;
0408             }
0409
0410             my $nr_reclaimed = $3;
0411             my $flags = $13;
0412             my $file = 0;
0413             if ($flags =~ /RECLAIM_WB_FILE/) {
0414                 $file = 1;
0415             }
0416             $perprocesspid{$process_pid}->{HIGH_NR_RECLAIMED} += $nr_reclaimed;
0417             if ($file) {
0418                 $perprocesspid{$process_pid}->{HIGH_NR_FILE_RECLAIMED} += $nr_reclaimed;
0419             } else {
0420                 $perprocesspid{$process_pid}->{HIGH_NR_ANON_RECLAIMED} += $nr_reclaimed;
0421             }
0422         } elsif ($tracepoint eq "mm_vmscan_writepage") {
0423             $details = $6;
0424             if ($details !~ /$regex_writepage/o) {
0425                 print "WARNING: Failed to parse mm_vmscan_writepage as expected\n";
0426                 print "         $details\n";
0427                 print "         $regex_writepage\n";
0428                 next;
0429             }
0430
0431             my $flags = $3;
0432             my $file = 0;
0433             my $sync_io = 0;
0434             if ($flags =~ /RECLAIM_WB_FILE/) {
0435                 $file = 1;
0436             }
0437             if ($flags =~ /RECLAIM_WB_SYNC/) {
0438                 $sync_io = 1;
0439             }
0440             if ($sync_io) {
0441                 if ($file) {
0442                     $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}++;
0443                 } else {
0444                     $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}++;
0445                 }
0446             } else {
0447                 if ($file) {
0448                     $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}++;
0449                 } else {
0450                     $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}++;
0451                 }
0452             }
0453         } else {
0454             $perprocesspid{$process_pid}->{EVENT_UNKNOWN}++;
0455         }
0456
0457         if ($sigint_pending) {
0458             last EVENT_PROCESS;
0459         }
0460     }
0461 }
0462
0463 sub dump_stats {
0464     my $hashref = shift;
0465     my %stats = %$hashref;
0466
0467     # Dump per-process stats
0468     my $process_pid;
0469     my $max_strlen = 0;
0470
0471     # Get the maximum process name
0472     foreach $process_pid (keys %perprocesspid) {
0473         my $len = length($process_pid);
0474         if ($len > $max_strlen) {
0475             $max_strlen = $len;
0476         }
0477     }
0478     $max_strlen += 2;
0479
0480     # Work out latencies
0481     printf("\n") if !$opt_ignorepid;
0482     printf("Reclaim latencies expressed as order-latency_in_ms\n") if !$opt_ignorepid;
0483     foreach $process_pid (keys %stats) {
0484
0485         if (!$stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[0] &&
0486                 !$stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[0]) {
0487             next;
0488         }
0489
0490         printf "%-" . $max_strlen . "s ", $process_pid if !$opt_ignorepid;
0491         my $index = 0;
0492         while (defined $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index] ||
0493             defined $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]) {
0494
0495             if ($stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) {
0496                 printf("%s ", $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) if !$opt_ignorepid;
0497                 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]);
0498                 $total_direct_latency += $latency;
0499             } else {
0500                 printf("%s ", $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]) if !$opt_ignorepid;
0501                 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]);
0502                 $total_kswapd_latency += $latency;
0503             }
0504             $index++;
0505         }
0506         print "\n" if !$opt_ignorepid;
0507     }
0508
0509     # Print out process activity
0510     printf("\n");
0511     printf("%-" . $max_strlen . "s %8s %10s   %8s %8s  %8s %8s %8s %8s\n", "Process", "Direct",  "Wokeup", "Pages",   "Pages",   "Pages",   "Pages",     "Time");
0512     printf("%-" . $max_strlen . "s %8s %10s   %8s %8s  %8s %8s %8s %8s\n", "details", "Rclms",   "Kswapd", "Scanned", "Rclmed",  "Sync-IO", "ASync-IO",  "Stalled");
0513     foreach $process_pid (keys %stats) {
0514
0515         if (!$stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}) {
0516             next;
0517         }
0518
0519         $total_direct_reclaim += $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN};
0520         $total_wakeup_kswapd += $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD};
0521         $total_direct_nr_scanned += $stats{$process_pid}->{HIGH_NR_SCANNED};
0522         $total_direct_nr_file_scanned += $stats{$process_pid}->{HIGH_NR_FILE_SCANNED};
0523         $total_direct_nr_anon_scanned += $stats{$process_pid}->{HIGH_NR_ANON_SCANNED};
0524         $total_direct_nr_reclaimed += $stats{$process_pid}->{HIGH_NR_RECLAIMED};
0525         $total_direct_nr_file_reclaimed += $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED};
0526         $total_direct_nr_anon_reclaimed += $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED};
0527         $total_direct_writepage_file_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC};
0528         $total_direct_writepage_anon_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC};
0529         $total_direct_writepage_file_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC};
0530
0531         $total_direct_writepage_anon_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC};
0532
0533         my $index = 0;
0534         my $this_reclaim_delay = 0;
0535         while (defined $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) {
0536              my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]);
0537             $this_reclaim_delay += $latency;
0538             $index++;
0539         }
0540
0541         printf("%-" . $max_strlen . "s %8d %10d   %8u %8u  %8u %8u %8.3f",
0542             $process_pid,
0543             $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN},
0544             $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD},
0545             $stats{$process_pid}->{HIGH_NR_SCANNED},
0546             $stats{$process_pid}->{HIGH_NR_FILE_SCANNED},
0547             $stats{$process_pid}->{HIGH_NR_ANON_SCANNED},
0548             $stats{$process_pid}->{HIGH_NR_RECLAIMED},
0549             $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED},
0550             $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED},
0551             $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC},
0552             $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC},
0553             $this_reclaim_delay / 1000);
0554
0555         if ($stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}) {
0556             print "      ";
0557             for (my $order = 0; $order < 20; $order++) {
0558                 my $count = $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order];
0559                 if ($count != 0) {
0560                     print "direct-$order=$count ";
0561                 }
0562             }
0563         }
0564         if ($stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}) {
0565             print "      ";
0566             for (my $order = 0; $order < 20; $order++) {
0567                 my $count = $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order];
0568                 if ($count != 0) {
0569                     print "wakeup-$order=$count ";
0570                 }
0571             }
0572         }
0573
0574         print "\n";
0575     }
0576
0577     # Print out kswapd activity
0578     printf("\n");
0579     printf("%-" . $max_strlen . "s %8s %10s   %8s   %8s %8s %8s\n", "Kswapd",   "Kswapd",  "Order",     "Pages",   "Pages",   "Pages",  "Pages");
0580     printf("%-" . $max_strlen . "s %8s %10s   %8s   %8s %8s %8s\n", "Instance", "Wakeups", "Re-wakeup", "Scanned", "Rclmed",  "Sync-IO", "ASync-IO");
0581     foreach $process_pid (keys %stats) {
0582
0583         if (!$stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}) {
0584             next;
0585         }
0586
0587         $total_kswapd_wake += $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE};
0588         $total_kswapd_nr_scanned += $stats{$process_pid}->{HIGH_NR_SCANNED};
0589         $total_kswapd_nr_file_scanned += $stats{$process_pid}->{HIGH_NR_FILE_SCANNED};
0590         $total_kswapd_nr_anon_scanned += $stats{$process_pid}->{HIGH_NR_ANON_SCANNED};
0591         $total_kswapd_nr_reclaimed += $stats{$process_pid}->{HIGH_NR_RECLAIMED};
0592         $total_kswapd_nr_file_reclaimed += $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED};
0593         $total_kswapd_nr_anon_reclaimed += $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED};
0594         $total_kswapd_writepage_file_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC};
0595         $total_kswapd_writepage_anon_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC};
0596         $total_kswapd_writepage_file_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC};
0597         $total_kswapd_writepage_anon_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC};
0598
0599         printf("%-" . $max_strlen . "s %8d %10d   %8u %8u  %8i %8u",
0600             $process_pid,
0601             $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE},
0602             $stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP},
0603             $stats{$process_pid}->{HIGH_NR_SCANNED},
0604             $stats{$process_pid}->{HIGH_NR_FILE_SCANNED},
0605             $stats{$process_pid}->{HIGH_NR_ANON_SCANNED},
0606             $stats{$process_pid}->{HIGH_NR_RECLAIMED},
0607             $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED},
0608             $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED},
0609             $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC},
0610             $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC});
0611
0612         if ($stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}) {
0613             print "      ";
0614             for (my $order = 0; $order < 20; $order++) {
0615                 my $count = $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order];
0616                 if ($count != 0) {
0617                     print "wake-$order=$count ";
0618                 }
0619             }
0620         }
0621         if ($stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP}) {
0622             print "      ";
0623             for (my $order = 0; $order < 20; $order++) {
0624                 my $count = $stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP_PERORDER}[$order];
0625                 if ($count != 0) {
0626                     print "rewake-$order=$count ";
0627                 }
0628             }
0629         }
0630         printf("\n");
0631     }
0632
0633     # Print out summaries
0634     $total_direct_latency /= 1000;
0635     $total_kswapd_latency /= 1000;
0636     print "\nSummary\n";
0637     print "Direct reclaims:                 $total_direct_reclaim\n";
0638     print "Direct reclaim pages scanned:        $total_direct_nr_scanned\n";
0639     print "Direct reclaim file pages scanned:   $total_direct_nr_file_scanned\n";
0640     print "Direct reclaim anon pages scanned:   $total_direct_nr_anon_scanned\n";
0641     print "Direct reclaim pages reclaimed:      $total_direct_nr_reclaimed\n";
0642     print "Direct reclaim file pages reclaimed: $total_direct_nr_file_reclaimed\n";
0643     print "Direct reclaim anon pages reclaimed: $total_direct_nr_anon_reclaimed\n";
0644     print "Direct reclaim write file sync I/O:  $total_direct_writepage_file_sync\n";
0645     print "Direct reclaim write anon sync I/O:  $total_direct_writepage_anon_sync\n";
0646     print "Direct reclaim write file async I/O: $total_direct_writepage_file_async\n";
0647     print "Direct reclaim write anon async I/O: $total_direct_writepage_anon_async\n";
0648     print "Wake kswapd requests:            $total_wakeup_kswapd\n";
0649     printf "Time stalled direct reclaim:        %-1.2f seconds\n", $total_direct_latency;
0650     print "\n";
0651     print "Kswapd wakeups:              $total_kswapd_wake\n";
0652     print "Kswapd pages scanned:            $total_kswapd_nr_scanned\n";
0653     print "Kswapd file pages scanned:       $total_kswapd_nr_file_scanned\n";
0654     print "Kswapd anon pages scanned:       $total_kswapd_nr_anon_scanned\n";
0655     print "Kswapd pages reclaimed:          $total_kswapd_nr_reclaimed\n";
0656     print "Kswapd file pages reclaimed:     $total_kswapd_nr_file_reclaimed\n";
0657     print "Kswapd anon pages reclaimed:     $total_kswapd_nr_anon_reclaimed\n";
0658     print "Kswapd reclaim write file sync I/O:  $total_kswapd_writepage_file_sync\n";
0659     print "Kswapd reclaim write anon sync I/O:  $total_kswapd_writepage_anon_sync\n";
0660     print "Kswapd reclaim write file async I/O: $total_kswapd_writepage_file_async\n";
0661     print "Kswapd reclaim write anon async I/O: $total_kswapd_writepage_anon_async\n";
0662     printf "Time kswapd awake:          %-1.2f seconds\n", $total_kswapd_latency;
0663 }
0664
0665 sub aggregate_perprocesspid() {
0666     my $process_pid;
0667     my $process;
0668     undef %perprocess;
0669
0670     foreach $process_pid (keys %perprocesspid) {
0671         $process = $process_pid;
0672         $process =~ s/-([0-9])*$//;
0673         if ($process eq '') {
0674             $process = "NO_PROCESS_NAME";
0675         }
0676
0677         $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN} += $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN};
0678         $perprocess{$process}->{MM_VMSCAN_KSWAPD_WAKE} += $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE};
0679         $perprocess{$process}->{MM_VMSCAN_WAKEUP_KSWAPD} += $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD};
0680         $perprocess{$process}->{HIGH_KSWAPD_REWAKEUP} += $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP};
0681         $perprocess{$process}->{HIGH_NR_SCANNED} += $perprocesspid{$process_pid}->{HIGH_NR_SCANNED};
0682         $perprocess{$process}->{HIGH_NR_FILE_SCANNED} += $perprocesspid{$process_pid}->{HIGH_NR_FILE_SCANNED};
0683         $perprocess{$process}->{HIGH_NR_ANON_SCANNED} += $perprocesspid{$process_pid}->{HIGH_NR_ANON_SCANNED};
0684         $perprocess{$process}->{HIGH_NR_RECLAIMED} += $perprocesspid{$process_pid}->{HIGH_NR_RECLAIMED};
0685         $perprocess{$process}->{HIGH_NR_FILE_RECLAIMED} += $perprocesspid{$process_pid}->{HIGH_NR_FILE_RECLAIMED};
0686         $perprocess{$process}->{HIGH_NR_ANON_RECLAIMED} += $perprocesspid{$process_pid}->{HIGH_NR_ANON_RECLAIMED};
0687         $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC};
0688         $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC};
0689         $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC};
0690         $perprocess{$process}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC};
0691
0692         for (my $order = 0; $order < 20; $order++) {
0693             $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order];
0694             $perprocess{$process}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order];
0695             $perprocess{$process}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order];
0696
0697         }
0698
0699         # Aggregate direct reclaim latencies
0700         my $wr_index = $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END};
0701         my $rd_index = 0;
0702         while (defined $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$rd_index]) {
0703             $perprocess{$process}->{HIGH_DIRECT_RECLAIM_LATENCY}[$wr_index] = $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$rd_index];
0704             $rd_index++;
0705             $wr_index++;
0706         }
0707         $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END} = $wr_index;
0708
0709         # Aggregate kswapd latencies
0710         my $wr_index = $perprocess{$process}->{MM_VMSCAN_KSWAPD_SLEEP};
0711         my $rd_index = 0;
0712         while (defined $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$rd_index]) {
0713             $perprocess{$process}->{HIGH_KSWAPD_LATENCY}[$wr_index] = $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$rd_index];
0714             $rd_index++;
0715             $wr_index++;
0716         }
0717         $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END} = $wr_index;
0718     }
0719 }
0720
0721 sub report() {
0722     if (!$opt_ignorepid) {
0723         dump_stats(\%perprocesspid);
0724     } else {
0725         aggregate_perprocesspid();
0726         dump_stats(\%perprocess);
0727     }
0728 }
0729
0730 # Process events or signals until neither is available
0731 sub signal_loop() {
0732     my $sigint_processed;
0733     do {
0734         $sigint_processed = 0;
0735         process_events();
0736
0737         # Handle pending signals if any
0738         if ($sigint_pending) {
0739             my $current_time = time;
0740
0741             if ($sigint_exit) {
0742                 print "Received exit signal\n";
0743                 $sigint_pending = 0;
0744             }
0745             if ($sigint_report) {
0746                 if ($current_time >= $sigint_received + 2) {
0747                     report();
0748                     $sigint_report = 0;
0749                     $sigint_pending = 0;
0750                     $sigint_processed = 1;
0751                 }
0752             }
0753         }
0754     } while ($sigint_pending || $sigint_processed);
0755 }
0756
0757 signal_loop();
0758 report();