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