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