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