Porting/harness-timer-report.pl

   1 #!perl -w
   2 #
   3 # harness-timer-report.pl
   4 #
   5 # - read in the HARNESS_TIMER=1 output of "make test"
   6 # - convert the milliseconds to seconds
   7 # - compute a couple of derived values
   8 #   - cpu: the sum of 'self' and 'kids'
   9 #   - ratio of the wallclock and the cpu
  10 # - optionally show header, the sum, or the max of each colum
  11 # - sort the rows in various ways
  12 #   - default ordering by 'cpu' seconds
  13 # - optionally scale the column values by either the sum or the max
  14 # - optionally display only rows that have rows of at least / at most a limit
  15 #
  16 # The --sort option has a few canned sorting rules.  If those are
  17 # not to your liking, there is always sort(1).
  18 #
  19 # Example usages:
  20 #
  21 # perl harness-timer-report.pl log
  22 # perl harness-timer-report.pl --sort=wall log
  23 # perl harness-timer-report.pl --scale=sum log
  24 # perl harness-timer-report.pl --scale=sum --min=0.01 log
  25 # perl harness-timer-report.pl --show=header,max,sum log
  26 # perl harness-timer-report.pl --min=wall=10 log
  27
  28 use strict;
  29 use warnings;
  30
  31 use File::Basename qw[basename];
  32
  33 our $ME = basename($0);
  34
  35 use Getopt::Long;
  36
  37 sub usage {
  38     die <<__EOF__;
  39 $ME: Usage:
  40 $ME [--scale=[sum|max]]
  41     [--sort=[cpu|wall|ratio|self|kids|test|name]]
  42     [--show=header,sum,max]
  43     [--min=[[cpu|wall|ratio|self|kids]=value,...]]
  44     [--max=[[cpu|wall|ratio|self|kids]=value,...]]
  45     [--order]
  46     [--help|--usage]
  47     [logfile]
  48
  49 The --order includes the original test order as the last column.
  50 The logfile default is STDIN.
  51 __EOF__
  52 }
  53
  54 my %Opt;
  55 usage()
  56     unless
  57     GetOptions(
  58         'scale=s' => \$Opt{scale},
  59         'sort=s'  => \$Opt{sort},
  60         'show=s' => \$Opt{show},
  61         'min=s' => \$Opt{min},
  62         'max=s' => \$Opt{max},
  63         'order' => \$Opt{order},
  64         'help|usage' => \$Opt{help},
  65     );
  66 usage() if $Opt{help};
  67
  68 my %SHOW;
  69 if (defined $Opt{show}) {
  70     for my $s (split(/,/, $Opt{show})) {
  71         if ($s =~ /^(header|sum|max)$/) {
  72             $SHOW{$s}++;
  73         } else {
  74             die "$ME: Unexpected --show='$s'\n";
  75         }
  76     }
  77 }
  78 my %MIN;
  79 if (defined $Opt{min}) {
  80     for my $s (split(/,/, $Opt{min})) {
  81         if ($s =~ /^(wall|cpu|kids|self|ratio)=(\d+(?:\.\d+)?)$/) {
  82             $MIN{$1} = $2;
  83         } else {
  84             die "$ME: Unexpected --min='$s'\n";
  85         }
  86     }
  87 }
  88 my %MAX;
  89 if (defined $Opt{max}) {
  90     for my $s (split(/,/, $Opt{max})) {
  91         if ($s =~ /^(wall|cpu|kids|self|ratio)=(\d+(?:\.\d+)?)$/) {
  92             $MAX{$1} = $2;
  93         } else {
  94             die "$ME: Unexpected --max='$s'\n";
  95         }
  96     }
  97 }
  98
  99 use List::Util qw[max];
 100
 101 my ($sa, $sb, $sc, $sd, $se);
 102 my ($ma, $mb, $mc, $md, $me);
 103
 104 my $logfn;
 105 my $logfh;
 106 if (@ARGV == 1) {
 107     $logfn = $ARGV[0];
 108     open($logfh, "<", $logfn) or die "$ME: Failed to open logfn: $logfn\n";
 109 } elsif (@ARGV == 0) {
 110     $logfn = "-";
 111     $logfh = *STDIN;
 112 } else {
 113     die "$ME: Unexpected logfile arguments: @ARGV\n";
 114 }
 115
 116 my $order = 0;
 117 my @t;
 118
 119 while (<$logfh>) {
 120     my ($test, $wall, $self, $kids);
 121     # Output of "env HARNESS_TIMER=1 make test":
 122     # t/re/pat ....................................................... ok     2876 ms  2660 ms   210 ms
 123     if (m{^#\s+(\S+)\s+\.+\s+ok\s+(\d+)\s+ms\s+(\d+)\s+ms\s+(\d+)\s+ms$}) {
 124         ($test, $wall, $self, $kids) = ($1, $2, $3, $4);
 125     }
 126     # Output of "env HARNESS_TIMER=1 make test_harness":
 127     # [08:26:11] base/cond.t ........................................................ ok        2 ms ( 0.00 usr  0.00 sys +  0.00 cusr  0.00 csys =  0.00 CPU)
 128     if (m{^\[.+?\]+\s+(\S+)\s+\.+\s+ok\s+(\d+)\s+ms\s+\(\s*(\d+\.\d+)\s+usr\s+\s+(\d+\.\d+)\s+sys\s+\+\s+(\d+\.\d+)\s+cusr\s+(\d+\.\d+)\s+csys\s+=\s+(\d+\.\d+)\s+CPU\)}) {
 129         $test = $1;
 130         $wall = $2;
 131         $self = $3 + $4;
 132         $kids = $5 + $6;
 133         $test =~ s{^\.\./}{};  # "../lib/foo" -> "../lib/foo"
 134     }
 135     next unless defined $test && defined $wall && $wall > 0;
 136     # Milliseconds to seconds.
 137     $wall /= 1000;
 138     $self /= 1000;
 139     $kids /= 1000;
 140     my $cpu = $self + $kids;
 141     my $ratio = $cpu / $wall;
 142     push @t, [ $test, $wall, $self, $kids, $cpu, $ratio, $order++ ];
 143     $sa += $wall;
 144     $sb += $self;
 145     $sc += $kids;
 146     $sd += $cpu;
 147     $ma = max($wall,  $ma // $wall);
 148     $mb = max($self,  $mb // $self);
 149     $mc = max($kids,  $mc // $kids);
 150     $md = max($cpu,   $md // $cpu);
 151     $me = max($ratio, $md // $ratio);
 152 }
 153
 154 die "$ME: No input detected in '$logfn'\n" unless @t;
 155
 156 # Compute the sum for the ratio only after the loop.
 157 $se = $sd / $sa;
 158
 159 my %SORTER =
 160     (
 161      'cpu' =>
 162       sub { $b->[4] <=> $a->[4] ||
 163             $b->[1] <=> $a->[1] ||
 164             $a->[0] cmp $b->[0] },
 165      'wall' =>
 166       sub { $b->[1] <=> $a->[1] ||
 167             $b->[4] <=> $a->[4] ||
 168             $a->[0] cmp $b->[0] },
 169      'ratio' =>
 170       sub { $b->[5] <=> $a->[5] ||
 171             $b->[4] <=> $a->[4] ||
 172             $b->[1] <=> $a->[1] ||
 173             $a->[0] cmp $b->[0] },
 174      'self' =>
 175       sub { $b->[2] <=> $a->[2] ||
 176             $b->[3] <=> $a->[3] ||
 177             $a->[0] cmp $b->[0] },
 178      'kids' =>
 179       sub { $b->[3] <=> $a->[3] ||
 180             $b->[2] <=> $a->[2] ||
 181             $a->[0] cmp $b->[0] },
 182      'test' =>
 183       sub { $a->[6] <=> $b->[6] },
 184      'name' =>
 185       sub { $a->[0] cmp $b->[0] },
 186     );
 187 my $sorter;
 188
 189 $Opt{sort} //= 'cpu';
 190
 191 die "$ME: Unexpected --sort='$Opt{sort}'\n"
 192     unless defined $SORTER{$Opt{sort}};
 193
 194 @t = sort { $SORTER{$Opt{sort}}->() } @t;
 195
 196 if (defined $Opt{scale}) {
 197     my ($ta, $tb, $tc, $td, $te) =
 198         $Opt{scale} eq 'sum' ?
 199         ($sa, $sb, $sc, $sd, $se) :
 200         $Opt{scale} eq 'max' ?
 201         ($ma, $mb, $mc, $md, $me) :
 202         die "$ME: Unexpected --scale='$Opt{scale}'";
 203
 204     my @u;
 205     for my $t (@t) {
 206     push @u, [ $t->[0],
 207                $t->[1] / $ta, $t->[2] / $tb,
 208                $t->[3] / $tc, $t->[4] / $td,
 209                $t->[5] / $te, $t->[6] ];
 210     }
 211     @t = @u;
 212 }
 213
 214 if ($SHOW{header}) {
 215     my @header = qw[TEST WALL SELF KIDS CPU RATIO];
 216     if ($Opt{order}) {
 217         push @header, 'ORDER';
 218     }
 219     print join(" ", @header), "\n";
 220 }
 221 if ($SHOW{sum}) {
 222     print join(" ", "SUM",
 223                map { sprintf("%.6f", $_) } $sa, $sb, $sc, $sd, $se),
 224           "\n";
 225 }
 226 if ($SHOW{max}) {
 227     print join(" ", "MAX",
 228                map { sprintf("%.6f", $_) } $ma, $mb, $mc, $md, $me),
 229           "\n";
 230 }
 231
 232 my %N2I = (wall  => 1,
 233            self  => 2,
 234            kids  => 3,
 235            cpu   => 4,
 236            ratio => 5);
 237
 238 sub row_is_skippable {
 239     my ($t) = @_;
 240     if (scalar keys %MIN) {
 241         for my $k (grep { exists $MIN{$_} } keys %N2I) {
 242             if ($t->[$N2I{$k}] < $MIN{$k}) {
 243                 return 1;
 244             }
 245         }
 246     }
 247     if (scalar keys %MAX) {
 248         for my $k (grep { exists $MAX{$_} } keys %N2I) {
 249             if ($t->[$N2I{$k}] > $MAX{$k}) {
 250                 return 1;
 251             }
 252         }
 253     }
 254     return 0;
 255 }
 256
 257 for my $t (@t) {
 258     next if row_is_skippable($t);
 259     my $out = sprintf("%s %.6f %.6f %.6f %.6f %.6f",
 260                       $t->[0], $t->[1], $t->[2], $t->[3], $t->[4], $t->[5]);
 261     if ($Opt{order}) {
 262         $out .= " $t->[6]";
 263     }
 264     print $out, "\n";
 265 }
 266
 267 exit(0);