Lines Matching +full:0 +full:- +full:9 +full:a +full:- +full:f
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
6 # Example usage: trace-vmscan-postprocess.pl < /sys/kernel/debug/tracing/trace_pipe
8 # --read-procstat If the trace lacks process info, get it from /proc
9 # --ignore-pid Aggregate processes of the same name together
25 use constant MM_VMSCAN_WRITEPAGE_ANON_SYNC => 9;
31 # Per-order events
43 # High-level events extrapolated from tracepoints
77 my $sigint_report = 0;
78 my $sigint_exit = 0;
79 my $sigint_pending = 0;
80 my $sigint_received = 0;
83 if ($current_time - 2 > $sigint_received) {
84 print "SIGINT received, report pending. Hit ctrl-c again to exit\n";
105 'ignore-pid' => \$opt_ignorepid,
106 'read-procstat' => \$opt_read_procstat,
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]*) gfp_flags=([A-Z_|]*)';
115 …te_mode=([0-9]*) classzone_idx=([0-9]*) order=([0-9]*) nr_requested=([0-9]*) nr_scanned=([0-9]*) n…
116 …0-9]*) nr_scanned=([0-9]*) nr_reclaimed=([0-9]*) nr_dirty=([0-9]*) nr_writeback=([0-9]*) nr_conges…
117 my $regex_lru_shrink_active_default = 'lru=([A-Z_]*) nr_scanned=([0-9]*) nr_rotated=([0-9]*) priori…
118 my $regex_writepage_default = 'page=([0-9a-f]*) pfn=([0-9]*) flags=([A-Z_|]*)';
133 my $regex_traceevent = '\s*([a-zA-Z0-9-]*)\s*(\[[0-9]*\])(\s*[dX.][Nnp.][Hhs.][0-9a-fA-F.]*|)\s*([0…
134 my $regex_statname = '[-0-9]*\s\((.*)\).*';
135 my $regex_statppid = '[-0-9]*\s\(.*\)\s[A-Za-z]\s([0-9]*).*';
150 $line =~ s/, REC->.*//;
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;
230 my $pid = $_[0];
239 $statline = "-1 (UNKNOWN_PROCESS_NAME) R 0";
246 my $pid = $_[0];
249 if ($pid == 0) {
250 return "swapper-0";
256 return "$1-$pid";
261 my $timestamp = $_[0];
284 $process_pid =~ /(.*)-([0-9]*)$/;
290 $process_pid = "$process-$pid";
307 $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}++;
308 $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN} = $timestamp;
318 $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order]++;
319 $perprocesspid{$process_pid}->{STATE_DIRECT_ORDER} = $order;
322 my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_END};
323 $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_END}++;
326 if (defined $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN}) {
328 my $order = $perprocesspid{$process_pid}->{STATE_DIRECT_ORDER};
329 my $latency = ($timestamp - $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN});
330 $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index] = "$order-$latency";
342 $perprocesspid{$process_pid}->{STATE_KSWAPD_ORDER} = $order;
343 if (!$perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN}) {
345 $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}++;
346 $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN} = $timestamp;
347 $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order]++;
349 $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP}++;
350 $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP_PERORDER}[$order]++;
355 my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP};
356 $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP}++;
360 my $order = $perprocesspid{$process_pid}->{STATE_KSWAPD_ORDER};
361 my $latency = ($timestamp - $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN});
362 $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index] = "$order-$latency";
363 $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN} = 0;
365 $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}++;
375 $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order]++;
394 $perprocesspid{$process_pid}->{HIGH_NR_SCANNED} += $nr_scanned;
396 $perprocesspid{$process_pid}->{HIGH_NR_FILE_SCANNED} += $nr_scanned;
398 $perprocesspid{$process_pid}->{HIGH_NR_ANON_SCANNED} += $nr_scanned;
412 my $file = 0;
416 $perprocesspid{$process_pid}->{HIGH_NR_RECLAIMED} += $nr_reclaimed;
418 $perprocesspid{$process_pid}->{HIGH_NR_FILE_RECLAIMED} += $nr_reclaimed;
420 $perprocesspid{$process_pid}->{HIGH_NR_ANON_RECLAIMED} += $nr_reclaimed;
432 my $file = 0;
433 my $sync_io = 0;
442 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}++;
444 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}++;
448 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}++;
450 $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}++;
454 $perprocesspid{$process_pid}->{EVENT_UNKNOWN}++;
467 # Dump per-process stats
469 my $max_strlen = 0;
482 printf("Reclaim latencies expressed as order-latency_in_ms\n") if !$opt_ignorepid;
485 if (!$stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[0] &&
486 !$stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[0]) {
490 printf "%-" . $max_strlen . "s ", $process_pid if !$opt_ignorepid;
491 my $index = 0;
492 while (defined $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index] ||
493 defined $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]) {
495 if ($stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) {
496 printf("%s ", $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) if !$opt_ignorepid;
497 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]);
500 printf("%s ", $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]) if !$opt_ignorepid;
501 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]);
511 …printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s %8s %8s\n", "Process", "Direct", "Woke…
512 …printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s %8s %8s\n", "details", "Rclms", "Kswa…
515 if (!$stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}) {
519 $total_direct_reclaim += $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN};
520 $total_wakeup_kswapd += $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD};
521 $total_direct_nr_scanned += $stats{$process_pid}->{HIGH_NR_SCANNED};
522 $total_direct_nr_file_scanned += $stats{$process_pid}->{HIGH_NR_FILE_SCANNED};
523 $total_direct_nr_anon_scanned += $stats{$process_pid}->{HIGH_NR_ANON_SCANNED};
524 $total_direct_nr_reclaimed += $stats{$process_pid}->{HIGH_NR_RECLAIMED};
525 $total_direct_nr_file_reclaimed += $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED};
526 $total_direct_nr_anon_reclaimed += $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED};
527 $total_direct_writepage_file_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC};
528 $total_direct_writepage_anon_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC};
529 $total_direct_writepage_file_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC};
531 $total_direct_writepage_anon_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC};
533 my $index = 0;
534 my $this_reclaim_delay = 0;
535 while (defined $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) {
536 my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]);
541 printf("%-" . $max_strlen . "s %8d %10d %8u %8u %8u %8u %8.3f",
543 $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN},
544 $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD},
545 $stats{$process_pid}->{HIGH_NR_SCANNED},
546 $stats{$process_pid}->{HIGH_NR_FILE_SCANNED},
547 $stats{$process_pid}->{HIGH_NR_ANON_SCANNED},
548 $stats{$process_pid}->{HIGH_NR_RECLAIMED},
549 $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED},
550 $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED},
551 …$stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE…
552 …$stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAG…
555 if ($stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}) {
557 for (my $order = 0; $order < 20; $order++) {
558 my $count = $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order];
559 if ($count != 0) {
560 print "direct-$order=$count ";
564 if ($stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}) {
566 for (my $order = 0; $order < 20; $order++) {
567 my $count = $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order];
568 if ($count != 0) {
569 print "wakeup-$order=$count ";
579 …printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s\n", "Kswapd", "Kswapd", "Order", …
580 …printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s\n", "Instance", "Wakeups", "Re-wakeup"…
583 if (!$stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}) {
587 $total_kswapd_wake += $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE};
588 $total_kswapd_nr_scanned += $stats{$process_pid}->{HIGH_NR_SCANNED};
589 $total_kswapd_nr_file_scanned += $stats{$process_pid}->{HIGH_NR_FILE_SCANNED};
590 $total_kswapd_nr_anon_scanned += $stats{$process_pid}->{HIGH_NR_ANON_SCANNED};
591 $total_kswapd_nr_reclaimed += $stats{$process_pid}->{HIGH_NR_RECLAIMED};
592 $total_kswapd_nr_file_reclaimed += $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED};
593 $total_kswapd_nr_anon_reclaimed += $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED};
594 $total_kswapd_writepage_file_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC};
595 $total_kswapd_writepage_anon_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC};
596 $total_kswapd_writepage_file_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC};
597 $total_kswapd_writepage_anon_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC};
599 printf("%-" . $max_strlen . "s %8d %10d %8u %8u %8i %8u",
601 $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE},
602 $stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP},
603 $stats{$process_pid}->{HIGH_NR_SCANNED},
604 $stats{$process_pid}->{HIGH_NR_FILE_SCANNED},
605 $stats{$process_pid}->{HIGH_NR_ANON_SCANNED},
606 $stats{$process_pid}->{HIGH_NR_RECLAIMED},
607 $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED},
608 $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED},
609 …$stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE…
610 …$stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAG…
612 if ($stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}) {
614 for (my $order = 0; $order < 20; $order++) {
615 my $count = $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order];
616 if ($count != 0) {
617 print "wake-$order=$count ";
621 if ($stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP}) {
623 for (my $order = 0; $order < 20; $order++) {
624 my $count = $stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP_PERORDER}[$order];
625 if ($count != 0) {
626 print "rewake-$order=$count ";
649 printf "Time stalled direct reclaim: %-1.2f seconds\n", $total_direct_latency;
662 printf "Time kswapd awake: %-1.2f seconds\n", $total_kswapd_latency;
672 $process =~ s/-([0-9])*$//;
677 …$perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN} += $perprocesspid{$process_pid}->{MM_VMSCA…
678 …$perprocess{$process}->{MM_VMSCAN_KSWAPD_WAKE} += $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_…
679 …$perprocess{$process}->{MM_VMSCAN_WAKEUP_KSWAPD} += $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEU…
680 …$perprocess{$process}->{HIGH_KSWAPD_REWAKEUP} += $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKE…
681 $perprocess{$process}->{HIGH_NR_SCANNED} += $perprocesspid{$process_pid}->{HIGH_NR_SCANNED};
682 …$perprocess{$process}->{HIGH_NR_FILE_SCANNED} += $perprocesspid{$process_pid}->{HIGH_NR_FILE_SCANN…
683 …$perprocess{$process}->{HIGH_NR_ANON_SCANNED} += $perprocesspid{$process_pid}->{HIGH_NR_ANON_SCANN…
684 $perprocess{$process}->{HIGH_NR_RECLAIMED} += $perprocesspid{$process_pid}->{HIGH_NR_RECLAIMED};
685 …$perprocess{$process}->{HIGH_NR_FILE_RECLAIMED} += $perprocesspid{$process_pid}->{HIGH_NR_FILE_REC…
686 …$perprocess{$process}->{HIGH_NR_ANON_RECLAIMED} += $perprocesspid{$process_pid}->{HIGH_NR_ANON_REC…
687 …$perprocess{$process}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN…
688 …$perprocess{$process}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC} += $perprocesspid{$process_pid}->{MM_VMSCAN…
689 …$perprocess{$process}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} += $perprocesspid{$process_pid}->{MM_VMSCA…
690 …$perprocess{$process}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC} += $perprocesspid{$process_pid}->{MM_VMSCA…
692 for (my $order = 0; $order < 20; $order++) {
693 …$perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order] += $perprocesspid{$proces…
694 …$perprocess{$process}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order] += $perprocesspid{$process_pid}-…
695 …$perprocess{$process}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order] += $perprocesspid{$process_pid}->{…
700 my $wr_index = $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END};
701 my $rd_index = 0;
702 while (defined $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$rd_index]) {
703 …$perprocess{$process}->{HIGH_DIRECT_RECLAIM_LATENCY}[$wr_index] = $perprocesspid{$process_pid}->{H…
707 $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END} = $wr_index;
710 my $wr_index = $perprocess{$process}->{MM_VMSCAN_KSWAPD_SLEEP};
711 my $rd_index = 0;
712 while (defined $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$rd_index]) {
713 …$perprocess{$process}->{HIGH_KSWAPD_LATENCY}[$wr_index] = $perprocesspid{$process_pid}->{HIGH_KSWA…
717 $perprocess{$process}->{MM_VMSCAN_DIRECT_RECLAIM_END} = $wr_index;
734 $sigint_processed = 0;
743 $sigint_pending = 0;
748 $sigint_report = 0;
749 $sigint_pending = 0;