Documentation/trace/postprocess/trace-vmscan-postprocess.pl

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