About Kernel Documentation Linux Kernel Contact Linux Resources Linux Blog

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




Custom Search

Based on kernel version 4.1. Page generated on 2015-06-28 12:14 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_FILE_SCANNED		=> 25;
51	use constant HIGH_NR_ANON_SCANNED		=> 26;
52	use constant HIGH_NR_FILE_RECLAIMED		=> 27;
53	use constant HIGH_NR_ANON_RECLAIMED		=> 28;
54	
55	my %perprocesspid;
56	my %perprocess;
57	my %last_procmap;
58	my $opt_ignorepid;
59	my $opt_read_procstat;
60	
61	my $total_wakeup_kswapd;
62	my ($total_direct_reclaim, $total_direct_nr_scanned);
63	my ($total_direct_nr_file_scanned, $total_direct_nr_anon_scanned);
64	my ($total_direct_latency, $total_kswapd_latency);
65	my ($total_direct_nr_reclaimed);
66	my ($total_direct_nr_file_reclaimed, $total_direct_nr_anon_reclaimed);
67	my ($total_direct_writepage_file_sync, $total_direct_writepage_file_async);
68	my ($total_direct_writepage_anon_sync, $total_direct_writepage_anon_async);
69	my ($total_kswapd_nr_scanned, $total_kswapd_wake);
70	my ($total_kswapd_nr_file_scanned, $total_kswapd_nr_anon_scanned);
71	my ($total_kswapd_writepage_file_sync, $total_kswapd_writepage_file_async);
72	my ($total_kswapd_writepage_anon_sync, $total_kswapd_writepage_anon_async);
73	my ($total_kswapd_nr_reclaimed);
74	my ($total_kswapd_nr_file_reclaimed, $total_kswapd_nr_anon_reclaimed);
75	
76	# Catch sigint and exit on request
77	my $sigint_report = 0;
78	my $sigint_exit = 0;
79	my $sigint_pending = 0;
80	my $sigint_received = 0;
81	sub 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
104	GetOptions(
105		'ignore-pid'	 =>	\$opt_ignorepid,
106		'read-procstat'	 =>	\$opt_read_procstat,
107	);
108	
109	# Defaults for dynamically discovered regex's
110	my $regex_direct_begin_default = 'order=([0-9]*) may_writepage=([0-9]*) gfp_flags=([A-Z_|]*)';
111	my $regex_direct_end_default = 'nr_reclaimed=([0-9]*)';
112	my $regex_kswapd_wake_default = 'nid=([0-9]*) order=([0-9]*)';
113	my $regex_kswapd_sleep_default = 'nid=([0-9]*)';
114	my $regex_wakeup_kswapd_default = 'nid=([0-9]*) zid=([0-9]*) order=([0-9]*)';
115	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]*)';
116	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_|]*)';
117	my $regex_lru_shrink_active_default = 'lru=([A-Z_]*) nr_scanned=([0-9]*) nr_rotated=([0-9]*) priority=([0-9]*)';
118	my $regex_writepage_default = 'page=([0-9a-f]*) pfn=([0-9]*) flags=([A-Z_|]*)';
119	
120	# Dyanically discovered regex
121	my $regex_direct_begin;
122	my $regex_direct_end;
123	my $regex_kswapd_wake;
124	my $regex_kswapd_sleep;
125	my $regex_wakeup_kswapd;
126	my $regex_lru_isolate;
127	my $regex_lru_shrink_inactive;
128	my $regex_lru_shrink_active;
129	my $regex_writepage;
130	
131	# Static regex used. Specified like this for readability and for use with /o
132	#                      (process_pid)     (cpus      )   ( time  )   (tpoint    ) (details)
133	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*(.*)';
134	my $regex_statname = '[-0-9]*\s\((.*)\).*';
135	my $regex_statppid = '[-0-9]*\s\(.*\)\s[A-Za-z]\s([0-9]*).*';
136	
137	sub 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");
205	$regex_lru_isolate = generate_traceevent_regex(
206				"vmscan/mm_vmscan_lru_isolate",
207				$regex_lru_isolate_default,
208				"isolate_mode", "order",
209				"nr_requested", "nr_scanned", "nr_taken",
210				"file");
211	$regex_lru_shrink_inactive = generate_traceevent_regex(
212				"vmscan/mm_vmscan_lru_shrink_inactive",
213				$regex_lru_shrink_inactive_default,
214				"nid", "zid",
215				"nr_scanned", "nr_reclaimed", "priority",
216				"flags");
217	$regex_lru_shrink_active = generate_traceevent_regex(
218				"vmscan/mm_vmscan_lru_shrink_active",
219				$regex_lru_shrink_active_default,
220				"nid", "zid",
221				"lru",
222				"nr_scanned", "nr_rotated", "priority");
223	$regex_writepage = generate_traceevent_regex(
224				"vmscan/mm_vmscan_writepage",
225				$regex_writepage_default,
226				"page", "pfn", "flags");
227	
228	sub read_statline($) {
229		my $pid = $_[0];
230		my $statline;
231	
232		if (open(STAT, "/proc/$pid/stat")) {
233			$statline = <STAT>;
234			close(STAT);
235		}
236	
237		if ($statline eq '') {
238			$statline = "-1 (UNKNOWN_PROCESS_NAME) R 0";
239		}
240	
241		return $statline;
242	}
243	
244	sub guess_process_pid($$) {
245		my $pid = $_[0];
246		my $statline = $_[1];
247	
248		if ($pid == 0) {
249			return "swapper-0";
250		}
251	
252		if ($statline !~ /$regex_statname/o) {
253			die("Failed to math stat line for process name :: $statline");
254		}
255		return "$1-$pid";
256	}
257	
258	# Convert sec.usec timestamp format
259	sub timestamp_to_ms($) {
260		my $timestamp = $_[0];
261	
262		my ($sec, $usec) = split (/\./, $timestamp);
263		return ($sec * 1000) + ($usec / 1000);
264	}
265	
266	sub process_events {
267		my $traceevent;
268		my $process_pid;
269		my $cpus;
270		my $timestamp;
271		my $tracepoint;
272		my $details;
273		my $statline;
274	
275		# Read each line of the event log
276	EVENT_PROCESS:
277		while ($traceevent = <STDIN>) {
278			if ($traceevent =~ /$regex_traceevent/o) {
279				$process_pid = $1;
280				$timestamp = $4;
281				$tracepoint = $5;
282	
283				$process_pid =~ /(.*)-([0-9]*)$/;
284				my $process = $1;
285				my $pid = $2;
286	
287				if ($process eq "") {
288					$process = $last_procmap{$pid};
289					$process_pid = "$process-$pid";
290				}
291				$last_procmap{$pid} = $process;
292	
293				if ($opt_read_procstat) {
294					$statline = read_statline($pid);
295					if ($opt_read_procstat && $process eq '') {
296						$process_pid = guess_process_pid($pid, $statline);
297					}
298				}
299			} else {
300				next;
301			}
302	
303			# Perl Switch() sucks majorly
304			if ($tracepoint eq "mm_vmscan_direct_reclaim_begin") {
305				$timestamp = timestamp_to_ms($timestamp);
306				$perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}++;
307				$perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN} = $timestamp;
308	
309				$details = $6;
310				if ($details !~ /$regex_direct_begin/o) {
311					print "WARNING: Failed to parse mm_vmscan_direct_reclaim_begin as expected\n";
312					print "         $details\n";
313					print "         $regex_direct_begin\n";
314					next;
315				}
316				my $order = $1;
317				$perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order]++;
318				$perprocesspid{$process_pid}->{STATE_DIRECT_ORDER} = $order;
319			} elsif ($tracepoint eq "mm_vmscan_direct_reclaim_end") {
320				# Count the event itself
321				my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_END};
322				$perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_END}++;
323	
324				# Record how long direct reclaim took this time
325				if (defined $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN}) {
326					$timestamp = timestamp_to_ms($timestamp);
327					my $order = $perprocesspid{$process_pid}->{STATE_DIRECT_ORDER};
328					my $latency = ($timestamp - $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN});
329					$perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index] = "$order-$latency";
330				}
331			} elsif ($tracepoint eq "mm_vmscan_kswapd_wake") {
332				$details = $6;
333				if ($details !~ /$regex_kswapd_wake/o) {
334					print "WARNING: Failed to parse mm_vmscan_kswapd_wake as expected\n";
335					print "         $details\n";
336					print "         $regex_kswapd_wake\n";
337					next;
338				}
339	
340				my $order = $2;
341				$perprocesspid{$process_pid}->{STATE_KSWAPD_ORDER} = $order;
342				if (!$perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN}) {
343					$timestamp = timestamp_to_ms($timestamp);
344					$perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}++;
345					$perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN} = $timestamp;
346					$perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order]++;
347				} else {
348					$perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP}++;
349					$perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP_PERORDER}[$order]++;
350				}
351			} elsif ($tracepoint eq "mm_vmscan_kswapd_sleep") {
352	
353				# Count the event itself
354				my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP};
355				$perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP}++;
356	
357				# Record how long kswapd was awake
358				$timestamp = timestamp_to_ms($timestamp);
359				my $order = $perprocesspid{$process_pid}->{STATE_KSWAPD_ORDER};
360				my $latency = ($timestamp - $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN});
361				$perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index] = "$order-$latency";
362				$perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN} = 0;
363			} elsif ($tracepoint eq "mm_vmscan_wakeup_kswapd") {
364				$perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}++;
365	
366				$details = $6;
367				if ($details !~ /$regex_wakeup_kswapd/o) {
368					print "WARNING: Failed to parse mm_vmscan_wakeup_kswapd as expected\n";
369					print "         $details\n";
370					print "         $regex_wakeup_kswapd\n";
371					next;
372				}
373				my $order = $3;
374				$perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order]++;
375			} elsif ($tracepoint eq "mm_vmscan_lru_isolate") {
376				$details = $6;
377				if ($details !~ /$regex_lru_isolate/o) {
378					print "WARNING: Failed to parse mm_vmscan_lru_isolate as expected\n";
379					print "         $details\n";
380					print "         $regex_lru_isolate/o\n";
381					next;
382				}
383				my $isolate_mode = $1;
384				my $nr_scanned = $4;
385				my $file = $6;
386	
387				# To closer match vmstat scanning statistics, only count isolate_both
388				# and isolate_inactive as scanning. isolate_active is rotation
389				# isolate_inactive == 1
390				# isolate_active   == 2
391				# isolate_both     == 3
392				if ($isolate_mode != 2) {
393					$perprocesspid{$process_pid}->{HIGH_NR_SCANNED} += $nr_scanned;
394					if ($file == 1) {
395						$perprocesspid{$process_pid}->{HIGH_NR_FILE_SCANNED} += $nr_scanned;
396					} else {
397						$perprocesspid{$process_pid}->{HIGH_NR_ANON_SCANNED} += $nr_scanned;
398					}
399				}
400			} elsif ($tracepoint eq "mm_vmscan_lru_shrink_inactive") {
401				$details = $6;
402				if ($details !~ /$regex_lru_shrink_inactive/o) {
403					print "WARNING: Failed to parse mm_vmscan_lru_shrink_inactive as expected\n";
404					print "         $details\n";
405					print "         $regex_lru_shrink_inactive/o\n";
406					next;
407				}
408	
409				my $nr_reclaimed = $4;
410				my $flags = $6;
411				my $file = 0;
412				if ($flags =~ /RECLAIM_WB_FILE/) {
413					$file = 1;
414				}
415				$perprocesspid{$process_pid}->{HIGH_NR_RECLAIMED} += $nr_reclaimed;
416				if ($file) {
417					$perprocesspid{$process_pid}->{HIGH_NR_FILE_RECLAIMED} += $nr_reclaimed;
418				} else {
419					$perprocesspid{$process_pid}->{HIGH_NR_ANON_RECLAIMED} += $nr_reclaimed;
420				}
421			} elsif ($tracepoint eq "mm_vmscan_writepage") {
422				$details = $6;
423				if ($details !~ /$regex_writepage/o) {
424					print "WARNING: Failed to parse mm_vmscan_writepage as expected\n";
425					print "         $details\n";
426					print "         $regex_writepage\n";
427					next;
428				}
429	
430				my $flags = $3;
431				my $file = 0;
432				my $sync_io = 0;
433				if ($flags =~ /RECLAIM_WB_FILE/) {
434					$file = 1;
435				}
436				if ($flags =~ /RECLAIM_WB_SYNC/) {
437					$sync_io = 1;
438				}
439				if ($sync_io) {
440					if ($file) {
441						$perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}++;
442					} else {
443						$perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}++;
444					}
445				} else {
446					if ($file) {
447						$perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}++;
448					} else {
449						$perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}++;
450					}
451				}
452			} else {
453				$perprocesspid{$process_pid}->{EVENT_UNKNOWN}++;
454			}
455	
456			if ($sigint_pending) {
457				last EVENT_PROCESS;
458			}
459		}
460	}
461	
462	sub dump_stats {
463		my $hashref = shift;
464		my %stats = %$hashref;
465	
466		# Dump per-process stats
467		my $process_pid;
468		my $max_strlen = 0;
469	
470		# Get the maximum process name
471		foreach $process_pid (keys %perprocesspid) {
472			my $len = length($process_pid);
473			if ($len > $max_strlen) {
474				$max_strlen = $len;
475			}
476		}
477		$max_strlen += 2;
478	
479		# Work out latencies
480		printf("\n") if !$opt_ignorepid;
481		printf("Reclaim latencies expressed as order-latency_in_ms\n") if !$opt_ignorepid;
482		foreach $process_pid (keys %stats) {
483	
484			if (!$stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[0] &&
485					!$stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[0]) {
486				next;
487			}
488	
489			printf "%-" . $max_strlen . "s ", $process_pid if !$opt_ignorepid;
490			my $index = 0;
491			while (defined $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index] ||
492				defined $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]) {
493	
494				if ($stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) {
495					printf("%s ", $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) if !$opt_ignorepid;
496					my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]);
497					$total_direct_latency += $latency;
498				} else {
499					printf("%s ", $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]) if !$opt_ignorepid;
500					my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]);
501					$total_kswapd_latency += $latency;
502				}
503				$index++;
504			}
505			print "\n" if !$opt_ignorepid;
506		}
507	
508		# Print out process activity
509		printf("\n");
510		printf("%-" . $max_strlen . "s %8s %10s   %8s %8s  %8s %8s %8s %8s\n", "Process", "Direct",  "Wokeup", "Pages",   "Pages",   "Pages",   "Pages",     "Time");
511		printf("%-" . $max_strlen . "s %8s %10s   %8s %8s  %8s %8s %8s %8s\n", "details", "Rclms",   "Kswapd", "Scanned", "Rclmed",  "Sync-IO", "ASync-IO",  "Stalled");
512		foreach $process_pid (keys %stats) {
513	
514			if (!$stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}) {
515				next;
516			}
517	
518			$total_direct_reclaim += $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN};
519			$total_wakeup_kswapd += $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD};
520			$total_direct_nr_scanned += $stats{$process_pid}->{HIGH_NR_SCANNED};
521			$total_direct_nr_file_scanned += $stats{$process_pid}->{HIGH_NR_FILE_SCANNED};
522			$total_direct_nr_anon_scanned += $stats{$process_pid}->{HIGH_NR_ANON_SCANNED};
523			$total_direct_nr_reclaimed += $stats{$process_pid}->{HIGH_NR_RECLAIMED};
524			$total_direct_nr_file_reclaimed += $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED};
525			$total_direct_nr_anon_reclaimed += $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED};
526			$total_direct_writepage_file_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC};
527			$total_direct_writepage_anon_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC};
528			$total_direct_writepage_file_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC};
529	
530			$total_direct_writepage_anon_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC};
531	
532			my $index = 0;
533			my $this_reclaim_delay = 0;
534			while (defined $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) {
535				 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]);
536				$this_reclaim_delay += $latency;
537				$index++;
538			}
539	
540			printf("%-" . $max_strlen . "s %8d %10d   %8u %8u  %8u %8u %8.3f",
541				$process_pid,
542				$stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN},
543				$stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD},
544				$stats{$process_pid}->{HIGH_NR_SCANNED},
545				$stats{$process_pid}->{HIGH_NR_FILE_SCANNED},
546				$stats{$process_pid}->{HIGH_NR_ANON_SCANNED},
547				$stats{$process_pid}->{HIGH_NR_RECLAIMED},
548				$stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED},
549				$stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED},
550				$stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC},
551				$stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC},
552				$this_reclaim_delay / 1000);
553	
554			if ($stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}) {
555				print "      ";
556				for (my $order = 0; $order < 20; $order++) {
557					my $count = $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order];
558					if ($count != 0) {
559						print "direct-$order=$count ";
560					}
561				}
562			}
563			if ($stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}) {
564				print "      ";
565				for (my $order = 0; $order < 20; $order++) {
566					my $count = $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order];
567					if ($count != 0) {
568						print "wakeup-$order=$count ";
569					}
570				}
571			}
572	
573			print "\n";
574		}
575	
576		# Print out kswapd activity
577		printf("\n");
578		printf("%-" . $max_strlen . "s %8s %10s   %8s   %8s %8s %8s\n", "Kswapd",   "Kswapd",  "Order",     "Pages",   "Pages",   "Pages",  "Pages");
579		printf("%-" . $max_strlen . "s %8s %10s   %8s   %8s %8s %8s\n", "Instance", "Wakeups", "Re-wakeup", "Scanned", "Rclmed",  "Sync-IO", "ASync-IO");
580		foreach $process_pid (keys %stats) {
581	
582			if (!$stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}) {
583				next;
584			}
585	
586			$total_kswapd_wake += $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE};
587			$total_kswapd_nr_scanned += $stats{$process_pid}->{HIGH_NR_SCANNED};
588			$total_kswapd_nr_file_scanned += $stats{$process_pid}->{HIGH_NR_FILE_SCANNED};
589			$total_kswapd_nr_anon_scanned += $stats{$process_pid}->{HIGH_NR_ANON_SCANNED};
590			$total_kswapd_nr_reclaimed += $stats{$process_pid}->{HIGH_NR_RECLAIMED};
591			$total_kswapd_nr_file_reclaimed += $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED};
592			$total_kswapd_nr_anon_reclaimed += $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED};
593			$total_kswapd_writepage_file_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC};
594			$total_kswapd_writepage_anon_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC};
595			$total_kswapd_writepage_file_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC};
596			$total_kswapd_writepage_anon_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC};
597	
598			printf("%-" . $max_strlen . "s %8d %10d   %8u %8u  %8i %8u",
599				$process_pid,
600				$stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE},
601				$stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP},
602				$stats{$process_pid}->{HIGH_NR_SCANNED},
603				$stats{$process_pid}->{HIGH_NR_FILE_SCANNED},
604				$stats{$process_pid}->{HIGH_NR_ANON_SCANNED},
605				$stats{$process_pid}->{HIGH_NR_RECLAIMED},
606				$stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED},
607				$stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED},
608				$stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC},
609				$stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC});
610	
611			if ($stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}) {
612				print "      ";
613				for (my $order = 0; $order < 20; $order++) {
614					my $count = $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order];
615					if ($count != 0) {
616						print "wake-$order=$count ";
617					}
618				}
619			}
620			if ($stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP}) {
621				print "      ";
622				for (my $order = 0; $order < 20; $order++) {
623					my $count = $stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP_PERORDER}[$order];
624					if ($count != 0) {
625						print "rewake-$order=$count ";
626					}
627				}
628			}
629			printf("\n");
630		}
631	
632		# Print out summaries
633		$total_direct_latency /= 1000;
634		$total_kswapd_latency /= 1000;
635		print "\nSummary\n";
636		print "Direct reclaims:     			$total_direct_reclaim\n";
637		print "Direct reclaim pages scanned:		$total_direct_nr_scanned\n";
638		print "Direct reclaim file pages scanned:	$total_direct_nr_file_scanned\n";
639		print "Direct reclaim anon pages scanned:	$total_direct_nr_anon_scanned\n";
640		print "Direct reclaim pages reclaimed:		$total_direct_nr_reclaimed\n";
641		print "Direct reclaim file pages reclaimed:	$total_direct_nr_file_reclaimed\n";
642		print "Direct reclaim anon pages reclaimed:	$total_direct_nr_anon_reclaimed\n";
643		print "Direct reclaim write file sync I/O:	$total_direct_writepage_file_sync\n";
644		print "Direct reclaim write anon sync I/O:	$total_direct_writepage_anon_sync\n";
645		print "Direct reclaim write file async I/O:	$total_direct_writepage_file_async\n";
646		print "Direct reclaim write anon async I/O:	$total_direct_writepage_anon_async\n";
647		print "Wake kswapd requests:			$total_wakeup_kswapd\n";
648		printf "Time stalled direct reclaim: 		%-1.2f seconds\n", $total_direct_latency;
649		print "\n";
650		print "Kswapd wakeups:				$total_kswapd_wake\n";
651		print "Kswapd pages scanned:			$total_kswapd_nr_scanned\n";
652		print "Kswapd file pages scanned:		$total_kswapd_nr_file_scanned\n";
653		print "Kswapd anon pages scanned:		$total_kswapd_nr_anon_scanned\n";
654		print "Kswapd pages reclaimed:			$total_kswapd_nr_reclaimed\n";
655		print "Kswapd file pages reclaimed:		$total_kswapd_nr_file_reclaimed\n";
656		print "Kswapd anon pages reclaimed:		$total_kswapd_nr_anon_reclaimed\n";
657		print "Kswapd reclaim write file sync I/O:	$total_kswapd_writepage_file_sync\n";
658		print "Kswapd reclaim write anon sync I/O:	$total_kswapd_writepage_anon_sync\n";
659		print "Kswapd reclaim write file async I/O:	$total_kswapd_writepage_file_async\n";
660		print "Kswapd reclaim write anon async I/O:	$total_kswapd_writepage_anon_async\n";
661		printf "Time kswapd awake:			%-1.2f seconds\n", $total_kswapd_latency;
662	}
663	
664	sub aggregate_perprocesspid() {
665		my $process_pid;
666		my $process;
667		undef %perprocess;
668	
669		foreach $process_pid (keys %perprocesspid) {
670			$process = $process_pid;
671			$process =~ s/-([0-9])*$//;
672			if ($process eq '') {
673				$process = "NO_PROCESS_NAME";
674			}
675	
676			$perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN} += $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN};
677			$perprocess{$process}->{MM_VMSCAN_KSWAPD_WAKE} += $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE};
678			$perprocess{$process}->{MM_VMSCAN_WAKEUP_KSWAPD} += $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD};
679			$perprocess{$process}->{HIGH_KSWAPD_REWAKEUP} += $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP};
680			$perprocess{$process}->{HIGH_NR_SCANNED} += $perprocesspid{$process_pid}->{HIGH_NR_SCANNED};
681			$perprocess{$process}->{HIGH_NR_FILE_SCANNED} += $perprocesspid{$process_pid}->{HIGH_NR_FILE_SCANNED};
682			$perprocess{$process}->{HIGH_NR_ANON_SCANNED} += $perprocesspid{$process_pid}->{HIGH_NR_ANON_SCANNED};
683			$perprocess{$process}->{HIGH_NR_RECLAIMED} += $perprocesspid{$process_pid}->{HIGH_NR_RECLAIMED};
684			$perprocess{$process}->{HIGH_NR_FILE_RECLAIMED} += $perprocesspid{$process_pid}->{HIGH_NR_FILE_RECLAIMED};
685			$perprocess{$process}->{HIGH_NR_ANON_RECLAIMED} += $perprocesspid{$process_pid}->{HIGH_NR_ANON_RECLAIMED};
686			$perprocess{$process}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC};
687			$perprocess{$process}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC};
688			$perprocess{$process}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC};
689			$perprocess{$process}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC};
690	
691			for (my $order = 0; $order < 20; $order++) {
692				$perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order];
693				$perprocess{$process}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order];
694				$perprocess{$process}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order] += $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order];
695	
696			}
697	
698			# Aggregate direct reclaim latencies
699			my $wr_index = $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END};
700			my $rd_index = 0;
701			while (defined $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$rd_index]) {
702				$perprocess{$process}->{HIGH_DIRECT_RECLAIM_LATENCY}[$wr_index] = $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$rd_index];
703				$rd_index++;
704				$wr_index++;
705			}
706			$perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END} = $wr_index;
707	
708			# Aggregate kswapd latencies
709			my $wr_index = $perprocess{$process}->{MM_VMSCAN_KSWAPD_SLEEP};
710			my $rd_index = 0;
711			while (defined $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$rd_index]) {
712				$perprocess{$process}->{HIGH_KSWAPD_LATENCY}[$wr_index] = $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$rd_index];
713				$rd_index++;
714				$wr_index++;
715			}
716			$perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END} = $wr_index;
717		}
718	}
719	
720	sub report() {
721		if (!$opt_ignorepid) {
722			dump_stats(\%perprocesspid);
723		} else {
724			aggregate_perprocesspid();
725			dump_stats(\%perprocess);
726		}
727	}
728	
729	# Process events or signals until neither is available
730	sub signal_loop() {
731		my $sigint_processed;
732		do {
733			$sigint_processed = 0;
734			process_events();
735	
736			# Handle pending signals if any
737			if ($sigint_pending) {
738				my $current_time = time;
739	
740				if ($sigint_exit) {
741					print "Received exit signal\n";
742					$sigint_pending = 0;
743				}
744				if ($sigint_report) {
745					if ($current_time >= $sigint_received + 2) {
746						report();
747						$sigint_report = 0;
748						$sigint_pending = 0;
749						$sigint_processed = 1;
750					}
751				}
752			}
753		} while ($sigint_pending || $sigint_processed);
754	}
755	
756	signal_loop();
757	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.