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