]>
Commit | Line | Data |
---|---|---|
b898cc70 MG |
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; | |
e11da5b4 | 49 | use constant HIGH_NR_RECLAIMED => 24; |
2c51856c CY |
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; | |
b898cc70 MG |
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); | |
2c51856c | 63 | my ($total_direct_nr_file_scanned, $total_direct_nr_anon_scanned); |
b898cc70 | 64 | my ($total_direct_latency, $total_kswapd_latency); |
e11da5b4 | 65 | my ($total_direct_nr_reclaimed); |
2c51856c | 66 | my ($total_direct_nr_file_reclaimed, $total_direct_nr_anon_reclaimed); |
b898cc70 MG |
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); | |
2c51856c | 70 | my ($total_kswapd_nr_file_scanned, $total_kswapd_nr_anon_scanned); |
b898cc70 MG |
71 | my ($total_kswapd_writepage_file_sync, $total_kswapd_writepage_file_async); |
72 | my ($total_kswapd_writepage_anon_sync, $total_kswapd_writepage_anon_async); | |
e11da5b4 | 73 | my ($total_kswapd_nr_reclaimed); |
2c51856c | 74 | my ($total_kswapd_nr_file_reclaimed, $total_kswapd_nr_anon_reclaimed); |
b898cc70 MG |
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]*)'; | |
5ecd9d40 | 114 | my $regex_wakeup_kswapd_default = 'nid=([0-9]*) zid=([0-9]*) order=([0-9]*) gfp_flags=([A-Z_|]*)'; |
93607e5a MH |
115 | my $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_]*)'; |
116 | my $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=([0-9]*) nr_ref_keep=([0-9]*) nr_unmap_fail=([0-9]*) priority=([0-9]*) flags=([A-Z_|]*)'; | |
b898cc70 MG |
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) | |
bd727816 | 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*(.*)'; |
b898cc70 MG |
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, | |
5ecd9d40 | 204 | "nid", "zid", "order", "gfp_flags"); |
b898cc70 MG |
205 | $regex_lru_isolate = generate_traceevent_regex( |
206 | "vmscan/mm_vmscan_lru_isolate", | |
207 | $regex_lru_isolate_default, | |
93607e5a MH |
208 | "isolate_mode", "classzone_idx", "order", |
209 | "nr_requested", "nr_scanned", "nr_skipped", "nr_taken", | |
210 | "lru"); | |
b898cc70 MG |
211 | $regex_lru_shrink_inactive = generate_traceevent_regex( |
212 | "vmscan/mm_vmscan_lru_shrink_inactive", | |
213 | $regex_lru_shrink_inactive_default, | |
93607e5a MH |
214 | "nid", "nr_scanned", "nr_reclaimed", "nr_dirty", "nr_writeback", |
215 | "nr_congested", "nr_immediate", "nr_activate", "nr_ref_keep", | |
216 | "nr_unmap_fail", "priority", "flags"); | |
b898cc70 MG |
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; | |
bd727816 VM |
280 | $timestamp = $4; |
281 | $tracepoint = $5; | |
b898cc70 MG |
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 | ||
bd727816 | 309 | $details = $6; |
b898cc70 MG |
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") { | |
bd727816 | 332 | $details = $6; |
b898cc70 MG |
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 | ||
bd727816 | 366 | $details = $6; |
b898cc70 MG |
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") { | |
bd727816 | 376 | $details = $6; |
b898cc70 MG |
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 | } | |
7a2d19bc | 383 | my $isolate_mode = $1; |
93607e5a MH |
384 | my $nr_scanned = $5; |
385 | my $file = $8; | |
7a2d19bc MG |
386 | |
387 | # To closer match vmstat scanning statistics, only count isolate_both | |
388 | # and isolate_inactive as scanning. isolate_active is rotation | |
4356f21d MK |
389 | # isolate_inactive == 1 |
390 | # isolate_active == 2 | |
391 | # isolate_both == 3 | |
392 | if ($isolate_mode != 2) { | |
7a2d19bc | 393 | $perprocesspid{$process_pid}->{HIGH_NR_SCANNED} += $nr_scanned; |
93607e5a | 394 | if ($file =~ /_file/) { |
2c51856c CY |
395 | $perprocesspid{$process_pid}->{HIGH_NR_FILE_SCANNED} += $nr_scanned; |
396 | } else { | |
397 | $perprocesspid{$process_pid}->{HIGH_NR_ANON_SCANNED} += $nr_scanned; | |
398 | } | |
7a2d19bc | 399 | } |
e11da5b4 | 400 | } elsif ($tracepoint eq "mm_vmscan_lru_shrink_inactive") { |
bd727816 | 401 | $details = $6; |
e11da5b4 MG |
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 | } | |
2c51856c | 408 | |
93607e5a MH |
409 | my $nr_reclaimed = $3; |
410 | my $flags = $12; | |
2c51856c CY |
411 | my $file = 0; |
412 | if ($flags =~ /RECLAIM_WB_FILE/) { | |
413 | $file = 1; | |
414 | } | |
e11da5b4 | 415 | $perprocesspid{$process_pid}->{HIGH_NR_RECLAIMED} += $nr_reclaimed; |
2c51856c CY |
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 | } | |
b898cc70 | 421 | } elsif ($tracepoint eq "mm_vmscan_writepage") { |
bd727816 | 422 | $details = $6; |
b898cc70 MG |
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"); | |
e11da5b4 MG |
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"); | |
b898cc70 MG |
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}; | |
2c51856c CY |
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}; | |
e11da5b4 | 523 | $total_direct_nr_reclaimed += $stats{$process_pid}->{HIGH_NR_RECLAIMED}; |
2c51856c CY |
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}; | |
b898cc70 MG |
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 | ||
e11da5b4 | 540 | printf("%-" . $max_strlen . "s %8d %10d %8u %8u %8u %8u %8.3f", |
b898cc70 MG |
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}, | |
2c51856c CY |
545 | $stats{$process_pid}->{HIGH_NR_FILE_SCANNED}, |
546 | $stats{$process_pid}->{HIGH_NR_ANON_SCANNED}, | |
e11da5b4 | 547 | $stats{$process_pid}->{HIGH_NR_RECLAIMED}, |
2c51856c CY |
548 | $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED}, |
549 | $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED}, | |
b898cc70 MG |
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 | } | |
b898cc70 MG |
572 | |
573 | print "\n"; | |
574 | } | |
575 | ||
576 | # Print out kswapd activity | |
577 | printf("\n"); | |
e11da5b4 MG |
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"); | |
b898cc70 MG |
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}; | |
2c51856c CY |
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}; | |
e11da5b4 | 590 | $total_kswapd_nr_reclaimed += $stats{$process_pid}->{HIGH_NR_RECLAIMED}; |
2c51856c CY |
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}; | |
b898cc70 MG |
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 | ||
e11da5b4 | 598 | printf("%-" . $max_strlen . "s %8d %10d %8u %8u %8i %8u", |
b898cc70 MG |
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}, | |
2c51856c CY |
603 | $stats{$process_pid}->{HIGH_NR_FILE_SCANNED}, |
604 | $stats{$process_pid}->{HIGH_NR_ANON_SCANNED}, | |
e11da5b4 | 605 | $stats{$process_pid}->{HIGH_NR_RECLAIMED}, |
2c51856c CY |
606 | $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED}, |
607 | $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED}, | |
b898cc70 MG |
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"; | |
2c51856c CY |
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"; | |
e11da5b4 | 640 | print "Direct reclaim pages reclaimed: $total_direct_nr_reclaimed\n"; |
2c51856c CY |
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"; | |
b898cc70 MG |
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"; | |
2c51856c CY |
652 | print "Kswapd file pages scanned: $total_kswapd_nr_file_scanned\n"; |
653 | print "Kswapd anon pages scanned: $total_kswapd_nr_anon_scanned\n"; | |
e11da5b4 | 654 | print "Kswapd pages reclaimed: $total_kswapd_nr_reclaimed\n"; |
2c51856c CY |
655 | print "Kswapd file pages reclaimed: $total_kswapd_nr_file_reclaimed\n"; |
656 | print "Kswapd anon pages reclaimed: $total_kswapd_nr_anon_reclaimed\n"; | |
b898cc70 MG |
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}; | |
2c51856c CY |
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}; | |
e11da5b4 | 683 | $perprocess{$process}->{HIGH_NR_RECLAIMED} += $perprocesspid{$process_pid}->{HIGH_NR_RECLAIMED}; |
2c51856c CY |
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}; | |
b898cc70 MG |
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(); |