1#!/usr/bin/env 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_anon=([0-9]*) nr_activate_file=([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_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
229sub 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
245sub 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
260sub timestamp_to_ms($) {
261	my $timestamp = $_[0];
262
263	my ($sec, $usec) = split (/\./, $timestamp);
264	return ($sec * 1000) + ($usec / 1000);
265}
266
267sub 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
277EVENT_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
463sub 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
665sub 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
721sub 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
731sub 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
757signal_loop();
758report();
759