Commit | Line | Data |
---|---|---|
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 | ||
30 | use strict; | |
31 | use warnings; | |
32 | ||
33 | use File::Basename qw[basename]; | |
34 | ||
35 | our $ME = basename($0); | |
36 | ||
37 | use Getopt::Long; | |
38 | ||
39 | sub 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 | |
51 | The --order includes the original test order as the last column. | |
a0d88a8f | 52 | The logfile default is STDIN. |
87af8d55 JH |
53 | __EOF__ |
54 | } | |
55 | ||
56 | my %Opt; | |
57 | usage() | |
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 | 68 | usage() if $Opt{help}; |
87af8d55 JH |
69 | |
70 | my %SHOW; | |
71 | if (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 | } | |
80 | my %MIN; | |
81 | if (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 | } | |
90 | my %MAX; | |
91 | if (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 | ||
101 | use List::Util qw[max]; | |
102 | ||
103 | my ($sa, $sb, $sc, $sd, $se); | |
104 | my ($ma, $mb, $mc, $md, $me); | |
105 | ||
a0d88a8f JH |
106 | my $logfn; |
107 | my $logfh; | |
108 | if (@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 |
118 | my $order = 0; |
119 | my @t; | |
a0d88a8f JH |
120 | |
121 | while (<$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 | 156 | die "$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 | ||
161 | my %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 | ); | |
189 | my $sorter; | |
190 | ||
191 | $Opt{sort} //= 'cpu'; | |
192 | ||
193 | die "$ME: Unexpected --sort='$Opt{sort}'\n" | |
194 | unless defined $SORTER{$Opt{sort}}; | |
195 | ||
196 | @t = sort { $SORTER{$Opt{sort}}->() } @t; | |
197 | ||
198 | if (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 | ||
216 | if ($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 | } | |
223 | if ($SHOW{sum}) { | |
224 | print join(" ", "SUM", | |
225 | map { sprintf("%.6f", $_) } $sa, $sb, $sc, $sd, $se), | |
226 | "\n"; | |
227 | } | |
228 | if ($SHOW{max}) { | |
229 | print join(" ", "MAX", | |
230 | map { sprintf("%.6f", $_) } $ma, $mb, $mc, $md, $me), | |
231 | "\n"; | |
232 | } | |
233 | ||
234 | my %N2I = (wall => 1, | |
235 | self => 2, | |
236 | kids => 3, | |
237 | cpu => 4, | |
238 | ratio => 5); | |
239 | ||
240 | sub 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 | ||
259 | for 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 | ||
269 | exit(0); |