About Kernel Documentation Linux Kernel Contact Linux Resources Linux Blog

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




Custom Search

Based on kernel version 3.16. Page generated on 2014-08-06 21:41 EST.

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

Information is copyright its respective author. All material is available from the Linux Kernel Source distributed under a GPL License. This page is provided as a free service by mjmwired.net.