trace-vmscan-postprocess.pl 28 KB

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