About Kernel Documentation Linux Kernel Contact Linux Resources Linux Blog

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




Custom Search

Based on kernel version 3.13. Page generated on 2014-01-20 22:04 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	use constant HIGH_NR_CONTIG_DIRTY		=> 25;
51	
52	my %perprocesspid;
53	my %perprocess;
54	my %last_procmap;
55	my $opt_ignorepid;
56	my $opt_read_procstat;
57	
58	my $total_wakeup_kswapd;
59	my ($total_direct_reclaim, $total_direct_nr_scanned);
60	my ($total_direct_latency, $total_kswapd_latency);
61	my ($total_direct_nr_reclaimed);
62	my ($total_direct_writepage_file_sync, $total_direct_writepage_file_async);
63	my ($total_direct_writepage_anon_sync, $total_direct_writepage_anon_async);
64	my ($total_kswapd_nr_scanned, $total_kswapd_wake);
65	my ($total_kswapd_writepage_file_sync, $total_kswapd_writepage_file_async);
66	my ($total_kswapd_writepage_anon_sync, $total_kswapd_writepage_anon_async);
67	my ($total_kswapd_nr_reclaimed);
68	
69	# Catch sigint and exit on request
70	my $sigint_report = 0;
71	my $sigint_exit = 0;
72	my $sigint_pending = 0;
73	my $sigint_received = 0;
74	sub 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
97	GetOptions(
98		'ignore-pid'	 =>	\$opt_ignorepid,
99		'read-procstat'	 =>	\$opt_read_procstat,
100	);
101	
102	# Defaults for dynamically discovered regex's
103	my $regex_direct_begin_default = 'order=([0-9]*) may_writepage=([0-9]*) gfp_flags=([A-Z_|]*)';
104	my $regex_direct_end_default = 'nr_reclaimed=([0-9]*)';
105	my $regex_kswapd_wake_default = 'nid=([0-9]*) order=([0-9]*)';
106	my $regex_kswapd_sleep_default = 'nid=([0-9]*)';
107	my $regex_wakeup_kswapd_default = 'nid=([0-9]*) zid=([0-9]*) order=([0-9]*)';
108	my $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]*)';
109	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_|]*)';
110	my $regex_lru_shrink_active_default = 'lru=([A-Z_]*) nr_scanned=([0-9]*) nr_rotated=([0-9]*) priority=([0-9]*)';
111	my $regex_writepage_default = 'page=([0-9a-f]*) pfn=([0-9]*) flags=([A-Z_|]*)';
112	
113	# Dyanically discovered regex
114	my $regex_direct_begin;
115	my $regex_direct_end;
116	my $regex_kswapd_wake;
117	my $regex_kswapd_sleep;
118	my $regex_wakeup_kswapd;
119	my $regex_lru_isolate;
120	my $regex_lru_shrink_inactive;
121	my $regex_lru_shrink_active;
122	my $regex_writepage;
123	
124	# Static regex used. Specified like this for readability and for use with /o
125	#                      (process_pid)     (cpus      )   ( time  )   (tpoint    ) (details)
126	my $regex_traceevent = '\s*([a-zA-Z0-9-]*)\s*(\[[0-9]*\])\s*([0-9.]*):\s*([a-zA-Z_]*):\s*(.*)';
127	my $regex_statname = '[-0-9]*\s\((.*)\).*';
128	my $regex_statppid = '[-0-9]*\s\(.*\)\s[A-Za-z]\s([0-9]*).*';
129	
130	sub 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	
221	sub 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	
237	sub 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
252	sub timestamp_to_ms($) {
253		my $timestamp = $_[0];
254	
255		my ($sec, $usec) = split (/\./, $timestamp);
256		return ($sec * 1000) + ($usec / 1000);
257	}
258	
259	sub 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
269	EVENT_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 == 1
383				# isolate_active   == 2
384				# isolate_both     == 3
385				if ($isolate_mode != 2) {
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	
440	sub 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	
625	sub 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	
677	sub 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
687	sub 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	
713	signal_loop();
714	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.