#!/usr/bin/env perl# This is a POC for reading the text representation of trace output related to# page reclaim. It makes an attempt to extract some high-level information on# what is going on. The accuracy of the parser may vary## Example usage: trace-vmscan-postprocess.pl < /sys/kernel/tracing/trace_pipe# other options# --read-procstat If the trace lacks process info, get it from /proc# --ignore-pid Aggregate processes of the same name together## Copyright (c) IBM Corporation 2009# Author: Mel Gorman <mel@csn.ul.ie>use strict;use Getopt::Long; # Tracepoint eventsuse constant MM_VMSCAN_DIRECT_RECLAIM_BEGIN => 1;use constant MM_VMSCAN_DIRECT_RECLAIM_END => 2;use constant MM_VMSCAN_KSWAPD_WAKE => 3;use constant MM_VMSCAN_KSWAPD_SLEEP => 4;use constant MM_VMSCAN_LRU_SHRINK_ACTIVE => 5;use constant MM_VMSCAN_LRU_SHRINK_INACTIVE => 6;use constant MM_VMSCAN_LRU_ISOLATE => 7;use constant MM_VMSCAN_WRITEPAGE_FILE_SYNC => 8;use constant MM_VMSCAN_WRITEPAGE_ANON_SYNC => 9;use constant MM_VMSCAN_WRITEPAGE_FILE_ASYNC => 10;use constant MM_VMSCAN_WRITEPAGE_ANON_ASYNC => 11;use constant MM_VMSCAN_WRITEPAGE_ASYNC => 12;use constant EVENT_UNKNOWN => 13; # Per-order eventsuse constant MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER => 11;use constant MM_VMSCAN_WAKEUP_KSWAPD_PERORDER => 12;use constant MM_VMSCAN_KSWAPD_WAKE_PERORDER => 13;use constant HIGH_KSWAPD_REWAKEUP_PERORDER => 14; # Constants used to track stateuse constant STATE_DIRECT_BEGIN => 15;use constant STATE_DIRECT_ORDER => 16;use constant STATE_KSWAPD_BEGIN => 17;use constant STATE_KSWAPD_ORDER => 18; # High-level events extrapolated from tracepointsuse constant HIGH_DIRECT_RECLAIM_LATENCY => 19;use constant HIGH_KSWAPD_LATENCY => 20;use constant HIGH_KSWAPD_REWAKEUP => 21;use constant HIGH_NR_SCANNED => 22;use constant HIGH_NR_TAKEN => 23;use constant HIGH_NR_RECLAIMED => 24;use constant HIGH_NR_FILE_SCANNED => 25;use constant HIGH_NR_ANON_SCANNED => 26;use constant HIGH_NR_FILE_RECLAIMED => 27;use constant HIGH_NR_ANON_RECLAIMED => 28; my %perprocesspid;my %perprocess;my %last_procmap;my $opt_ignorepid;my $opt_read_procstat; my $total_wakeup_kswapd;my ($total_direct_reclaim, $total_direct_nr_scanned);my ($total_direct_nr_file_scanned, $total_direct_nr_anon_scanned);my ($total_direct_latency, $total_kswapd_latency);my ($total_direct_nr_reclaimed);my ($total_direct_nr_file_reclaimed, $total_direct_nr_anon_reclaimed);my ($total_direct_writepage_file_sync, $total_direct_writepage_file_async);my ($total_direct_writepage_anon_sync, $total_direct_writepage_anon_async);my ($total_kswapd_nr_scanned, $total_kswapd_wake);my ($total_kswapd_nr_file_scanned, $total_kswapd_nr_anon_scanned);my ($total_kswapd_writepage_file_sync, $total_kswapd_writepage_file_async);my ($total_kswapd_writepage_anon_sync, $total_kswapd_writepage_anon_async);my ($total_kswapd_nr_reclaimed);my ($total_kswapd_nr_file_reclaimed, $total_kswapd_nr_anon_reclaimed); # Catch sigint and exit on requestmy $sigint_report = 0;my $sigint_exit = 0;my $sigint_pending = 0;my $sigint_received = 0;sub sigint_handler { my $current_time = time; if ($current_time - 2 > $sigint_received) { print "SIGINT received, report pending. Hit ctrl-c again to exit\n"; $sigint_report = 1; } else { if (!$sigint_exit) { print "Second SIGINT received quickly, exiting\n"; } $sigint_exit++; } if ($sigint_exit > 3) { print "Many SIGINTs received, exiting now without report\n"; exit; } $sigint_received = $current_time; $sigint_pending = 1;}$SIG{INT} = "sigint_handler"; # Parse command line optionsGetOptions( 'ignore-pid' => \$opt_ignorepid, 'read-procstat' => \$opt_read_procstat,); # Defaults for dynamically discovered regex'smy $regex_direct_begin_default = 'order=([0-9]*) gfp_flags=([A-Z_|]*)';my $regex_direct_end_default = 'nr_reclaimed=([0-9]*)';my $regex_kswapd_wake_default = 'nid=([0-9]*) order=([0-9]*)';my $regex_kswapd_sleep_default = 'nid=([0-9]*)';my $regex_wakeup_kswapd_default = 'nid=([0-9]*) order=([0-9]*) gfp_flags=([A-Z_|]*)';my $regex_lru_isolate_default = 'classzone=([0-9]*) order=([0-9]*) nr_requested=([0-9]*) nr_scanned=([0-9]*) nr_skipped=([0-9]*) nr_taken=([0-9]*) lru=([a-z_]*)';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_|]*)';my $regex_lru_shrink_active_default = 'lru=([A-Z_]*) nr_taken=([0-9]*) nr_active=([0-9]*) nr_deactivated=([0-9]*) nr_referenced=([0-9]*) priority=([0-9]*) flags=([A-Z_|]*)' ;my $regex_writepage_default = 'page=([0-9a-f]*) pfn=([0-9]*) flags=([A-Z_|]*)'; # Dyanically discovered regexmy $regex_direct_begin;my $regex_direct_end;my $regex_kswapd_wake;my $regex_kswapd_sleep;my $regex_wakeup_kswapd;my $regex_lru_isolate;my $regex_lru_shrink_inactive;my $regex_lru_shrink_active;my $regex_writepage; # Static regex used. Specified like this for readability and for use with /o# (process_pid) (cpus ) ( time ) (tpoint ) (details)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*(.*)';my $regex_statname = '[-0-9]*\s\((.*)\).*';my $regex_statppid = '[-0-9]*\s\(.*\)\s[A-Za-z]\s([0-9]*).*'; sub generate_traceevent_regex { my $event = shift; my $default = shift; my $regex; # Read the event format or use the default if (!open (FORMAT, "/sys/kernel/tracing/events/$event/format")) { print("WARNING: Event $event format string not found\n"); return $default; } else { my $line; while (!eof(FORMAT)) { $line = <FORMAT>; $line =~ s/, REC->.*//; if ($line =~ /^print fmt:\s"(.*)".*/) { $regex = $1; $regex =~ s/%s/\([0-9a-zA-Z|_]*\)/g; $regex =~ s/%p/\([0-9a-f]*\)/g; $regex =~ s/%d/\([-0-9]*\)/g; $regex =~ s/%ld/\([-0-9]*\)/g; $regex =~ s/%lu/\([0-9]*\)/g; } } } # Can't handle the print_flags stuff but in the context of this # script, it really doesn't matter $regex =~ s/\(REC.*\) \? __print_flags.*//; # Verify fields are in the right order my $tuple; foreach $tuple (split /\s/, $regex) { my ($key, $value) = split(/=/, $tuple); my $expected = shift; if ($key ne $expected) { print("WARNING: Format not as expected for event $event '$key' != '$expected'\n"); $regex =~ s/$key=\((.*)\)/$key=$1/; } } if (defined shift) { die("Fewer fields than expected in format"); } return $regex;} $regex_direct_begin = generate_traceevent_regex( "vmscan/mm_vmscan_direct_reclaim_begin", $regex_direct_begin_default, "order", "gfp_flags");$regex_direct_end = generate_traceevent_regex( "vmscan/mm_vmscan_direct_reclaim_end", $regex_direct_end_default, "nr_reclaimed");$regex_kswapd_wake = generate_traceevent_regex( "vmscan/mm_vmscan_kswapd_wake", $regex_kswapd_wake_default, "nid", "order");$regex_kswapd_sleep = generate_traceevent_regex( "vmscan/mm_vmscan_kswapd_sleep", $regex_kswapd_sleep_default, "nid");$regex_wakeup_kswapd = generate_traceevent_regex( "vmscan/mm_vmscan_wakeup_kswapd", $regex_wakeup_kswapd_default, "nid", "order", "gfp_flags");$regex_lru_isolate = generate_traceevent_regex( "vmscan/mm_vmscan_lru_isolate", $regex_lru_isolate_default, "classzone", "order", "nr_requested", "nr_scanned", "nr_skipped", "nr_taken", "lru");$regex_lru_shrink_inactive = generate_traceevent_regex( "vmscan/mm_vmscan_lru_shrink_inactive", $regex_lru_shrink_inactive_default, "nid", "nr_scanned", "nr_reclaimed", "nr_dirty", "nr_writeback", "nr_congested", "nr_immediate", "nr_activate_anon", "nr_activate_file", "nr_ref_keep", "nr_unmap_fail", "priority", "flags");$regex_lru_shrink_active = generate_traceevent_regex( "vmscan/mm_vmscan_lru_shrink_active", $regex_lru_shrink_active_default, "nid", "nr_taken", "nr_active", "nr_deactivated", "nr_referenced", "priority", "flags");$regex_writepage = generate_traceevent_regex( "vmscan/mm_vmscan_write_folio", $regex_writepage_default, "page", "pfn", "flags"); sub read_statline($) { my $pid = $_[0]; my $statline; if (open(STAT, "/proc/$pid/stat")) { $statline = <STAT>; close(STAT); } if ($statline eq '') { $statline = "-1 (UNKNOWN_PROCESS_NAME) R 0"; } return $statline;} sub guess_process_pid($$) { my $pid = $_[0]; my $statline = $_[1]; if ($pid == 0) { return "swapper-0"; } if ($statline !~ /$regex_statname/o) { die("Failed to math stat line for process name :: $statline"); } return "$1-$pid";} # Convert sec.usec timestamp formatsub timestamp_to_ms($) { my $timestamp = $_[0]; my ($sec, $usec) = split (/\./, $timestamp); return ($sec * 1000) + ($usec / 1000);} sub process_events { my $traceevent; my $process_pid; my $cpus; my $timestamp; my $tracepoint; my $details; my $statline; # Read each line of the event logEVENT_PROCESS: while ($traceevent = <STDIN>) { if ($traceevent =~ /$regex_traceevent/o) { $process_pid = $1; $timestamp = $4; $tracepoint = $5; $process_pid =~ /(.*)-([0-9]*)$/; my $process = $1; my $pid = $2; if ($process eq "") { $process = $last_procmap{$pid}; $process_pid = "$process-$pid"; } $last_procmap{$pid} = $process; if ($opt_read_procstat) { $statline = read_statline($pid); if ($opt_read_procstat && $process eq '') { $process_pid = guess_process_pid($pid, $statline); } } } else { next; } # Perl Switch() sucks majorly if ($tracepoint eq "mm_vmscan_direct_reclaim_begin") { $timestamp = timestamp_to_ms($timestamp); $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}++; $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN} = $timestamp; $details = $6; if ($details !~ /$regex_direct_begin/o) { print "WARNING: Failed to parse mm_vmscan_direct_reclaim_begin as expected\n"; print " $details\n"; print " $regex_direct_begin\n"; next; } my $order = $1; $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order]++; $perprocesspid{$process_pid}->{STATE_DIRECT_ORDER} = $order; } elsif ($tracepoint eq "mm_vmscan_direct_reclaim_end") { # Count the event itself my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_END}; $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_END}++; # Record how long direct reclaim took this time if (defined $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN}) { $timestamp = timestamp_to_ms($timestamp); my $order = $perprocesspid{$process_pid}->{STATE_DIRECT_ORDER}; my $latency = ($timestamp - $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN}); $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index] = "$order-$latency"; } } elsif ($tracepoint eq "mm_vmscan_kswapd_wake") { $details = $6; if ($details !~ /$regex_kswapd_wake/o) { print "WARNING: Failed to parse mm_vmscan_kswapd_wake as expected\n"; print " $details\n"; print " $regex_kswapd_wake\n"; next; } my $order = $2; $perprocesspid{$process_pid}->{STATE_KSWAPD_ORDER} = $order; if (!$perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN}) { $timestamp = timestamp_to_ms($timestamp); $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}++; $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN} = $timestamp; $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order]++; } else { $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP}++; $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP_PERORDER}[$order]++; } } elsif ($tracepoint eq "mm_vmscan_kswapd_sleep") { # Count the event itself my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP}; $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP}++; # Record how long kswapd was awake $timestamp = timestamp_to_ms($timestamp); my $order = $perprocesspid{$process_pid}->{STATE_KSWAPD_ORDER}; my $latency = ($timestamp - $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN}); $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index] = "$order-$latency"; $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN} = 0; } elsif ($tracepoint eq "mm_vmscan_wakeup_kswapd") { $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}++; $details = $6; if ($details !~ /$regex_wakeup_kswapd/o) { print "WARNING: Failed to parse mm_vmscan_wakeup_kswapd as expected\n"; print " $details\n"; print " $regex_wakeup_kswapd\n"; next; } my $order = $2; $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order]++; } elsif ($tracepoint eq "mm_vmscan_lru_isolate") { $details = $6; if ($details !~ /$regex_lru_isolate/o) { print "WARNING: Failed to parse mm_vmscan_lru_isolate as expected\n"; print " $details\n"; print " $regex_lru_isolate/o\n"; next; } my $nr_scanned = $4; my $lru = $7; # To closer match vmstat scanning statistics, only count # inactive lru as scanning if ($lru =~ /inactive_/) { $perprocesspid{$process_pid}->{HIGH_NR_SCANNED} += $nr_scanned; if ($lru =~ /_file/) { $perprocesspid{$process_pid}->{HIGH_NR_FILE_SCANNED} += $nr_scanned; } else { $perprocesspid{$process_pid}->{HIGH_NR_ANON_SCANNED} += $nr_scanned; } } } elsif ($tracepoint eq "mm_vmscan_lru_shrink_inactive") { $details = $6; if ($details !~ /$regex_lru_shrink_inactive/o) { print "WARNING: Failed to parse mm_vmscan_lru_shrink_inactive as expected\n"; print " $details\n"; print " $regex_lru_shrink_inactive/o\n"; next; } my $nr_reclaimed = $3; my $flags = $13; my $file = 0; if ($flags =~ /RECLAIM_WB_FILE/) { $file = 1; } $perprocesspid{$process_pid}->{HIGH_NR_RECLAIMED} += $nr_reclaimed; if ($file) { $perprocesspid{$process_pid}->{HIGH_NR_FILE_RECLAIMED} += $nr_reclaimed; } else { $perprocesspid{$process_pid}->{HIGH_NR_ANON_RECLAIMED} += $nr_reclaimed; } } elsif ($tracepoint eq "mm_vmscan_writepage") { $details = $6; if ($details !~ /$regex_writepage/o) { print "WARNING: Failed to parse mm_vmscan_writepage as expected\n"; print " $details\n"; print " $regex_writepage\n"; next; } my $flags = $3; my $file = 0; my $sync_io = 0; if ($flags =~ /RECLAIM_WB_FILE/) { $file = 1; } if ($flags =~ /RECLAIM_WB_SYNC/) { $sync_io = 1; } if ($sync_io) { if ($file) { $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}++; } else { $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}++; } } else { if ($file) { $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}++; } else { $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}++; } } } else { $perprocesspid{$process_pid}->{EVENT_UNKNOWN}++; } if ($sigint_pending) { last EVENT_PROCESS; } }} 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;Lines 1–500 of 752. Load more
#!/usr/bin/env perl # This is a POC for reading the text representation of trace output related to # page reclaim. It makes an attempt to extract some high-level information on # what is going on. The accuracy of the parser may vary # # Example usage: trace-vmscan-postprocess.pl < /sys/kernel/tracing/trace_pipe # other options # --read-procstat If the trace lacks process info, get it from /proc # --ignore-pid Aggregate processes of the same name together # # Copyright (c) IBM Corporation 2009 # Author: Mel Gorman <mel@csn.ul.ie> use strict; use Getopt::Long; # Tracepoint events use constant MM_VMSCAN_DIRECT_RECLAIM_BEGIN => 1; use constant MM_VMSCAN_DIRECT_RECLAIM_END => 2; use constant MM_VMSCAN_KSWAPD_WAKE => 3; use constant MM_VMSCAN_KSWAPD_SLEEP => 4; use constant MM_VMSCAN_LRU_SHRINK_ACTIVE => 5; use constant MM_VMSCAN_LRU_SHRINK_INACTIVE => 6; use constant MM_VMSCAN_LRU_ISOLATE => 7; use constant MM_VMSCAN_WRITEPAGE_FILE_SYNC => 8; use constant MM_VMSCAN_WRITEPAGE_ANON_SYNC => 9; use constant MM_VMSCAN_WRITEPAGE_FILE_ASYNC => 10; use constant MM_VMSCAN_WRITEPAGE_ANON_ASYNC => 11; use constant MM_VMSCAN_WRITEPAGE_ASYNC => 12; use constant EVENT_UNKNOWN => 13; # Per-order events use constant MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER => 11; use constant MM_VMSCAN_WAKEUP_KSWAPD_PERORDER => 12; use constant MM_VMSCAN_KSWAPD_WAKE_PERORDER => 13; use constant HIGH_KSWAPD_REWAKEUP_PERORDER => 14; # Constants used to track state use constant STATE_DIRECT_BEGIN => 15; use constant STATE_DIRECT_ORDER => 16; use constant STATE_KSWAPD_BEGIN => 17; use constant STATE_KSWAPD_ORDER => 18; # High-level events extrapolated from tracepoints use constant HIGH_DIRECT_RECLAIM_LATENCY => 19; use constant HIGH_KSWAPD_LATENCY => 20; use constant HIGH_KSWAPD_REWAKEUP => 21; use constant HIGH_NR_SCANNED => 22; use constant HIGH_NR_TAKEN => 23; use constant HIGH_NR_RECLAIMED => 24; use constant HIGH_NR_FILE_SCANNED => 25; use constant HIGH_NR_ANON_SCANNED => 26; use constant HIGH_NR_FILE_RECLAIMED => 27; use constant HIGH_NR_ANON_RECLAIMED => 28; my %perprocesspid; my %perprocess; my %last_procmap; my $opt_ignorepid; my $opt_read_procstat; my $total_wakeup_kswapd; my ($total_direct_reclaim, $total_direct_nr_scanned); my ($total_direct_nr_file_scanned, $total_direct_nr_anon_scanned); my ($total_direct_latency, $total_kswapd_latency); my ($total_direct_nr_reclaimed); my ($total_direct_nr_file_reclaimed, $total_direct_nr_anon_reclaimed); my ($total_direct_writepage_file_sync, $total_direct_writepage_file_async); my ($total_direct_writepage_anon_sync, $total_direct_writepage_anon_async); my ($total_kswapd_nr_scanned, $total_kswapd_wake); my ($total_kswapd_nr_file_scanned, $total_kswapd_nr_anon_scanned); my ($total_kswapd_writepage_file_sync, $total_kswapd_writepage_file_async); my ($total_kswapd_writepage_anon_sync, $total_kswapd_writepage_anon_async); my ($total_kswapd_nr_reclaimed); my ($total_kswapd_nr_file_reclaimed, $total_kswapd_nr_anon_reclaimed); # Catch sigint and exit on request my $sigint_report = 0; my $sigint_exit = 0; my $sigint_pending = 0; my $sigint_received = 0; sub sigint_handler { my $current_time = time; if ($current_time - 2 > $sigint_received) { print "SIGINT received, report pending. Hit ctrl-c again to exit\n"; $sigint_report = 1; } else { if (!$sigint_exit) { print "Second SIGINT received quickly, exiting\n"; } $sigint_exit++; } if ($sigint_exit > 3) { print "Many SIGINTs received, exiting now without report\n"; exit; } $sigint_received = $current_time; $sigint_pending = 1; } $SIG{INT} = "sigint_handler"; # Parse command line options GetOptions( 'ignore-pid' => \$opt_ignorepid, 'read-procstat' => \$opt_read_procstat, ); # Defaults for dynamically discovered regex's my $regex_direct_begin_default = 'order=([0-9]*) gfp_flags=([A-Z_|]*)'; my $regex_direct_end_default = 'nr_reclaimed=([0-9]*)'; my $regex_kswapd_wake_default = 'nid=([0-9]*) order=([0-9]*)'; my $regex_kswapd_sleep_default = 'nid=([0-9]*)'; my $regex_wakeup_kswapd_default = 'nid=([0-9]*) order=([0-9]*) gfp_flags=([A-Z_|]*)'; my $regex_lru_isolate_default = 'classzone=([0-9]*) order=([0-9]*) nr_requested=([0-9]*) nr_scanned=([0-9]*) nr_skipped=([0-9]*) nr_taken=([0-9]*) lru=([a-z_]*)'; 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_|]*)'; my $regex_lru_shrink_active_default = 'lru=([A-Z_]*) nr_taken=([0-9]*) nr_active=([0-9]*) nr_deactivated=([0-9]*) nr_referenced=([0-9]*) priority=([0-9]*) flags=([A-Z_|]*)' ; my $regex_writepage_default = 'page=([0-9a-f]*) pfn=([0-9]*) flags=([A-Z_|]*)'; # Dyanically discovered regex my $regex_direct_begin; my $regex_direct_end; my $regex_kswapd_wake; my $regex_kswapd_sleep; my $regex_wakeup_kswapd; my $regex_lru_isolate; my $regex_lru_shrink_inactive; my $regex_lru_shrink_active; my $regex_writepage; # Static regex used. Specified like this for readability and for use with /o # (process_pid) (cpus ) ( time ) (tpoint ) (details) 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*(.*)'; my $regex_statname = '[-0-9]*\s\((.*)\).*'; my $regex_statppid = '[-0-9]*\s\(.*\)\s[A-Za-z]\s([0-9]*).*'; sub generate_traceevent_regex { my $event = shift; my $default = shift; my $regex; # Read the event format or use the default if (!open (FORMAT, "/sys/kernel/tracing/events/$event/format")) { print("WARNING: Event $event format string not found\n"); return $default; } else { my $line; while (!eof(FORMAT)) { $line = <FORMAT>; $line =~ s/, REC->.*//; if ($line =~ /^print fmt:\s"(.*)".*/) { $regex = $1; $regex =~ s/%s/\([0-9a-zA-Z|_]*\)/g; $regex =~ s/%p/\([0-9a-f]*\)/g; $regex =~ s/%d/\([-0-9]*\)/g; $regex =~ s/%ld/\([-0-9]*\)/g; $regex =~ s/%lu/\([0-9]*\)/g; } } } # Can't handle the print_flags stuff but in the context of this # script, it really doesn't matter $regex =~ s/\(REC.*\) \? __print_flags.*//; # Verify fields are in the right order my $tuple; foreach $tuple (split /\s/, $regex) { my ($key, $value) = split(/=/, $tuple); my $expected = shift; if ($key ne $expected) { print("WARNING: Format not as expected for event $event '$key' != '$expected'\n"); $regex =~ s/$key=\((.*)\)/$key=$1/; } } if (defined shift) { die("Fewer fields than expected in format"); } return $regex; } $regex_direct_begin = generate_traceevent_regex( "vmscan/mm_vmscan_direct_reclaim_begin", $regex_direct_begin_default, "order", "gfp_flags"); $regex_direct_end = generate_traceevent_regex( "vmscan/mm_vmscan_direct_reclaim_end", $regex_direct_end_default, "nr_reclaimed"); $regex_kswapd_wake = generate_traceevent_regex( "vmscan/mm_vmscan_kswapd_wake", $regex_kswapd_wake_default, "nid", "order"); $regex_kswapd_sleep = generate_traceevent_regex( "vmscan/mm_vmscan_kswapd_sleep", $regex_kswapd_sleep_default, "nid"); $regex_wakeup_kswapd = generate_traceevent_regex( "vmscan/mm_vmscan_wakeup_kswapd", $regex_wakeup_kswapd_default, "nid", "order", "gfp_flags"); $regex_lru_isolate = generate_traceevent_regex( "vmscan/mm_vmscan_lru_isolate", $regex_lru_isolate_default, "classzone", "order", "nr_requested", "nr_scanned", "nr_skipped", "nr_taken", "lru"); $regex_lru_shrink_inactive = generate_traceevent_regex( "vmscan/mm_vmscan_lru_shrink_inactive", $regex_lru_shrink_inactive_default, "nid", "nr_scanned", "nr_reclaimed", "nr_dirty", "nr_writeback", "nr_congested", "nr_immediate", "nr_activate_anon", "nr_activate_file", "nr_ref_keep", "nr_unmap_fail", "priority", "flags"); $regex_lru_shrink_active = generate_traceevent_regex( "vmscan/mm_vmscan_lru_shrink_active", $regex_lru_shrink_active_default, "nid", "nr_taken", "nr_active", "nr_deactivated", "nr_referenced", "priority", "flags"); $regex_writepage = generate_traceevent_regex( "vmscan/mm_vmscan_write_folio", $regex_writepage_default, "page", "pfn", "flags"); sub read_statline($) { my $pid = $_[0]; my $statline; if (open(STAT, "/proc/$pid/stat")) { $statline = <STAT>; close(STAT); } if ($statline eq '') { $statline = "-1 (UNKNOWN_PROCESS_NAME) R 0"; } return $statline; } sub guess_process_pid($$) { my $pid = $_[0]; my $statline = $_[1]; if ($pid == 0) { return "swapper-0"; } if ($statline !~ /$regex_statname/o) { die("Failed to math stat line for process name :: $statline"); } return "$1-$pid"; } # Convert sec.usec timestamp format sub timestamp_to_ms($) { my $timestamp = $_[0]; my ($sec, $usec) = split (/\./, $timestamp); return ($sec * 1000) + ($usec / 1000); } sub process_events { my $traceevent; my $process_pid; my $cpus; my $timestamp; my $tracepoint; my $details; my $statline; # Read each line of the event log EVENT_PROCESS: while ($traceevent = <STDIN>) { if ($traceevent =~ /$regex_traceevent/o) { $process_pid = $1; $timestamp = $4; $tracepoint = $5; $process_pid =~ /(.*)-([0-9]*)$/; my $process = $1; my $pid = $2; if ($process eq "") { $process = $last_procmap{$pid}; $process_pid = "$process-$pid"; } $last_procmap{$pid} = $process; if ($opt_read_procstat) { $statline = read_statline($pid); if ($opt_read_procstat && $process eq '') { $process_pid = guess_process_pid($pid, $statline); } } } else { next; } # Perl Switch() sucks majorly if ($tracepoint eq "mm_vmscan_direct_reclaim_begin") { $timestamp = timestamp_to_ms($timestamp); $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN}++; $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN} = $timestamp; $details = $6; if ($details !~ /$regex_direct_begin/o) { print "WARNING: Failed to parse mm_vmscan_direct_reclaim_begin as expected\n"; print " $details\n"; print " $regex_direct_begin\n"; next; } my $order = $1; $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_BEGIN_PERORDER}[$order]++; $perprocesspid{$process_pid}->{STATE_DIRECT_ORDER} = $order; } elsif ($tracepoint eq "mm_vmscan_direct_reclaim_end") { # Count the event itself my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_END}; $perprocesspid{$process_pid}->{MM_VMSCAN_DIRECT_RECLAIM_END}++; # Record how long direct reclaim took this time if (defined $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN}) { $timestamp = timestamp_to_ms($timestamp); my $order = $perprocesspid{$process_pid}->{STATE_DIRECT_ORDER}; my $latency = ($timestamp - $perprocesspid{$process_pid}->{STATE_DIRECT_BEGIN}); $perprocesspid{$process_pid}->{HIGH_DIRECT_RECLAIM_LATENCY}[$index] = "$order-$latency"; } } elsif ($tracepoint eq "mm_vmscan_kswapd_wake") { $details = $6; if ($details !~ /$regex_kswapd_wake/o) { print "WARNING: Failed to parse mm_vmscan_kswapd_wake as expected\n"; print " $details\n"; print " $regex_kswapd_wake\n"; next; } my $order = $2; $perprocesspid{$process_pid}->{STATE_KSWAPD_ORDER} = $order; if (!$perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN}) { $timestamp = timestamp_to_ms($timestamp); $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE}++; $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN} = $timestamp; $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_WAKE_PERORDER}[$order]++; } else { $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP}++; $perprocesspid{$process_pid}->{HIGH_KSWAPD_REWAKEUP_PERORDER}[$order]++; } } elsif ($tracepoint eq "mm_vmscan_kswapd_sleep") { # Count the event itself my $index = $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP}; $perprocesspid{$process_pid}->{MM_VMSCAN_KSWAPD_SLEEP}++; # Record how long kswapd was awake $timestamp = timestamp_to_ms($timestamp); my $order = $perprocesspid{$process_pid}->{STATE_KSWAPD_ORDER}; my $latency = ($timestamp - $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN}); $perprocesspid{$process_pid}->{HIGH_KSWAPD_LATENCY}[$index] = "$order-$latency"; $perprocesspid{$process_pid}->{STATE_KSWAPD_BEGIN} = 0; } elsif ($tracepoint eq "mm_vmscan_wakeup_kswapd") { $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD}++; $details = $6; if ($details !~ /$regex_wakeup_kswapd/o) { print "WARNING: Failed to parse mm_vmscan_wakeup_kswapd as expected\n"; print " $details\n"; print " $regex_wakeup_kswapd\n"; next; } my $order = $2; $perprocesspid{$process_pid}->{MM_VMSCAN_WAKEUP_KSWAPD_PERORDER}[$order]++; } elsif ($tracepoint eq "mm_vmscan_lru_isolate") { $details = $6; if ($details !~ /$regex_lru_isolate/o) { print "WARNING: Failed to parse mm_vmscan_lru_isolate as expected\n"; print " $details\n"; print " $regex_lru_isolate/o\n"; next; } my $nr_scanned = $4; my $lru = $7; # To closer match vmstat scanning statistics, only count # inactive lru as scanning if ($lru =~ /inactive_/) { $perprocesspid{$process_pid}->{HIGH_NR_SCANNED} += $nr_scanned; if ($lru =~ /_file/) { $perprocesspid{$process_pid}->{HIGH_NR_FILE_SCANNED} += $nr_scanned; } else { $perprocesspid{$process_pid}->{HIGH_NR_ANON_SCANNED} += $nr_scanned; } } } elsif ($tracepoint eq "mm_vmscan_lru_shrink_inactive") { $details = $6; if ($details !~ /$regex_lru_shrink_inactive/o) { print "WARNING: Failed to parse mm_vmscan_lru_shrink_inactive as expected\n"; print " $details\n"; print " $regex_lru_shrink_inactive/o\n"; next; } my $nr_reclaimed = $3; my $flags = $13; my $file = 0; if ($flags =~ /RECLAIM_WB_FILE/) { $file = 1; } $perprocesspid{$process_pid}->{HIGH_NR_RECLAIMED} += $nr_reclaimed; if ($file) { $perprocesspid{$process_pid}->{HIGH_NR_FILE_RECLAIMED} += $nr_reclaimed; } else { $perprocesspid{$process_pid}->{HIGH_NR_ANON_RECLAIMED} += $nr_reclaimed; } } elsif ($tracepoint eq "mm_vmscan_writepage") { $details = $6; if ($details !~ /$regex_writepage/o) { print "WARNING: Failed to parse mm_vmscan_writepage as expected\n"; print " $details\n"; print " $regex_writepage\n"; next; } my $flags = $3; my $file = 0; my $sync_io = 0; if ($flags =~ /RECLAIM_WB_FILE/) { $file = 1; } if ($flags =~ /RECLAIM_WB_SYNC/) { $sync_io = 1; } if ($sync_io) { if ($file) { $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_SYNC}++; } else { $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_SYNC}++; } } else { if ($file) { $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_FILE_ASYNC}++; } else { $perprocesspid{$process_pid}->{MM_VMSCAN_WRITEPAGE_ANON_ASYNC}++; } } } else { $perprocesspid{$process_pid}->{EVENT_UNKNOWN}++; } if ($sigint_pending) { last EVENT_PROCESS; } } } 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;