in trace/postprocess/trace-vmscan-postprocess.pl [463:663]
sub dump_stats {
my $hashref = shift;
my %stats = %$hashref;
# Dump per-process stats
my $process_pid;
my $max_strlen = 0;
# Get the maximum process name
foreach $process_pid (keys %perprocesspid) {
my $len = length($process_pid);
if ($len > $max_strlen) {
$max_strlen = $len;
}
}
$max_strlen += 2;
# Work out latencies
printf("\n") if !$opt_ignorepid;
printf("Reclaim latencies expressed as order-latency_in_ms\n") if !$opt_ignorepid;
foreach $process_pid (keys %stats) {
if (!$stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[0] &&
!$stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[0]) {
next;
}
printf "%-" . $max_strlen . "s ", $process_pid if !$opt_ignorepid;
my $index = 0;
while (defined $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index] ||
defined $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]) {
if ($stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) {
printf("%s ", $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) if !$opt_ignorepid;
my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]);
$total_direct_latency += $latency;
} else {
printf("%s ", $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]) if !$opt_ignorepid;
my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index]);
$total_kswapd_latency += $latency;
}
$index++;
}
print "\n" if !$opt_ignorepid;
}
# Print out process activity
printf("\n");
printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s %8s %8s\n", "Process", "Direct", "Wokeup", "Pages", "Pages", "Pages", "Pages", "Time");
printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s %8s %8s\n", "details", "Rclms", "Kswapd", "Scanned", "Rclmed", "Sync-IO", "ASync-IO", "Stalled");
foreach $process_pid (keys %stats) {
if (!$stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}) {
next;
}
$total_direct_reclaim += $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN};
$total_wakeup_kswapd += $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD};
$total_direct_nr_scanned += $stats{$process_pid}->{HIGH_NR_SCANNED};
$total_direct_nr_file_scanned += $stats{$process_pid}->{HIGH_NR_FILE_SCANNED};
$total_direct_nr_anon_scanned += $stats{$process_pid}->{HIGH_NR_ANON_SCANNED};
$total_direct_nr_reclaimed += $stats{$process_pid}->{HIGH_NR_RECLAIMED};
$total_direct_nr_file_reclaimed += $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED};
$total_direct_nr_anon_reclaimed += $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED};
$total_direct_writepage_file_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC};
$total_direct_writepage_anon_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC};
$total_direct_writepage_file_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC};
$total_direct_writepage_anon_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC};
my $index = 0;
my $this_reclaim_delay = 0;
while (defined $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]) {
my ($dummy, $latency) = split(/-/, $stats{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index]);
$this_reclaim_delay += $latency;
$index++;
}
printf("%-" . $max_strlen . "s %8d %10d %8u %8u %8u %8u %8.3f",
$process_pid,
$stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN},
$stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD},
$stats{$process_pid}->{HIGH_NR_SCANNED},
$stats{$process_pid}->{HIGH_NR_FILE_SCANNED},
$stats{$process_pid}->{HIGH_NR_ANON_SCANNED},
$stats{$process_pid}->{HIGH_NR_RECLAIMED},
$stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED},
$stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED},
$stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC},
$stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC},
$this_reclaim_delay / 1000);
if ($stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}) {
print " ";
for (my $order = 0; $order < 20; $order++) {
my $count = $stats{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order];
if ($count != 0) {
print "direct-$order=$count ";
}
}
}
if ($stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}) {
print " ";
for (my $order = 0; $order < 20; $order++) {
my $count = $stats{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order];
if ($count != 0) {
print "wakeup-$order=$count ";
}
}
}
print "\n";
}
# Print out kswapd activity
printf("\n");
printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s\n", "Kswapd", "Kswapd", "Order", "Pages", "Pages", "Pages", "Pages");
printf("%-" . $max_strlen . "s %8s %10s %8s %8s %8s %8s\n", "Instance", "Wakeups", "Re-wakeup", "Scanned", "Rclmed", "Sync-IO", "ASync-IO");
foreach $process_pid (keys %stats) {
if (!$stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}) {
next;
}
$total_kswapd_wake += $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE};
$total_kswapd_nr_scanned += $stats{$process_pid}->{HIGH_NR_SCANNED};
$total_kswapd_nr_file_scanned += $stats{$process_pid}->{HIGH_NR_FILE_SCANNED};
$total_kswapd_nr_anon_scanned += $stats{$process_pid}->{HIGH_NR_ANON_SCANNED};
$total_kswapd_nr_reclaimed += $stats{$process_pid}->{HIGH_NR_RECLAIMED};
$total_kswapd_nr_file_reclaimed += $stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED};
$total_kswapd_nr_anon_reclaimed += $stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED};
$total_kswapd_writepage_file_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC};
$total_kswapd_writepage_anon_sync += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC};
$total_kswapd_writepage_file_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC};
$total_kswapd_writepage_anon_async += $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC};
printf("%-" . $max_strlen . "s %8d %10d %8u %8u %8i %8u",
$process_pid,
$stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE},
$stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP},
$stats{$process_pid}->{HIGH_NR_SCANNED},
$stats{$process_pid}->{HIGH_NR_FILE_SCANNED},
$stats{$process_pid}->{HIGH_NR_ANON_SCANNED},
$stats{$process_pid}->{HIGH_NR_RECLAIMED},
$stats{$process_pid}->{HIGH_NR_FILE_RECLAIMED},
$stats{$process_pid}->{HIGH_NR_ANON_RECLAIMED},
$stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC},
$stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC} + $stats{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC});
if ($stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}) {
print " ";
for (my $order = 0; $order < 20; $order++) {
my $count = $stats{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order];
if ($count != 0) {
print "wake-$order=$count ";
}
}
}
if ($stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP}) {
print " ";
for (my $order = 0; $order < 20; $order++) {
my $count = $stats{$process_pid}->{HIGH_KSWAPD_REWAKEUP_PERORDER}[$order];
if ($count != 0) {
print "rewake-$order=$count ";
}
}
}
printf("\n");
}
# Print out summaries
$total_direct_latency /= 1000;
$total_kswapd_latency /= 1000;
print "\nSummary\n";
print "Direct reclaims: $total_direct_reclaim\n";
print "Direct reclaim pages scanned: $total_direct_nr_scanned\n";
print "Direct reclaim file pages scanned: $total_direct_nr_file_scanned\n";
print "Direct reclaim anon pages scanned: $total_direct_nr_anon_scanned\n";
print "Direct reclaim pages reclaimed: $total_direct_nr_reclaimed\n";
print "Direct reclaim file pages reclaimed: $total_direct_nr_file_reclaimed\n";
print "Direct reclaim anon pages reclaimed: $total_direct_nr_anon_reclaimed\n";
print "Direct reclaim write file sync I/O: $total_direct_writepage_file_sync\n";
print "Direct reclaim write anon sync I/O: $total_direct_writepage_anon_sync\n";
print "Direct reclaim write file async I/O: $total_direct_writepage_file_async\n";
print "Direct reclaim write anon async I/O: $total_direct_writepage_anon_async\n";
print "Wake kswapd requests: $total_wakeup_kswapd\n";
printf "Time stalled direct reclaim: %-1.2f seconds\n", $total_direct_latency;
print "\n";
print "Kswapd wakeups: $total_kswapd_wake\n";
print "Kswapd pages scanned: $total_kswapd_nr_scanned\n";
print "Kswapd file pages scanned: $total_kswapd_nr_file_scanned\n";
print "Kswapd anon pages scanned: $total_kswapd_nr_anon_scanned\n";
print "Kswapd pages reclaimed: $total_kswapd_nr_reclaimed\n";
print "Kswapd file pages reclaimed: $total_kswapd_nr_file_reclaimed\n";
print "Kswapd anon pages reclaimed: $total_kswapd_nr_anon_reclaimed\n";
print "Kswapd reclaim write file sync I/O: $total_kswapd_writepage_file_sync\n";
print "Kswapd reclaim write anon sync I/O: $total_kswapd_writepage_anon_sync\n";
print "Kswapd reclaim write file async I/O: $total_kswapd_writepage_file_async\n";
print "Kswapd reclaim write anon async I/O: $total_kswapd_writepage_anon_async\n";
printf "Time kswapd awake: %-1.2f seconds\n", $total_kswapd_latency;
}