This is a live mirror of the Perl 5 development currently hosted at https://github.com/perl/perl5
Benchmark test from Nicholas Clark.
[perl5.git] / lib / Benchmark.t
CommitLineData
0e74ff8e
JH
1#!./perl -w
2
3BEGIN {
4 chdir 't' if -d 't';
5 @INC = '../lib';
6}
7
8use warnings;
9use strict;
10use vars qw($foo $bar $baz $ballast);
11use Test::More tests => 159;
12
13use Benchmark qw(:all);
14
15my $delta = 0.2;
16
17# Some timing ballast
18sub fib {
19 my $n = shift;
20 return $n if $n < 2;
21 fib($n-1) + fib($n-2);
22}
23$ballast = 15;
24
25my $all_pattern =
26 qr/(\d+) +wallclock secs? +\( *(-?\d+\.\d\d) +usr +(-?\d+\.\d\d) +sys +\+ +(-?\d+\.\d\d) +cusr +(-?\d+\.\d\d) +csys += +(-?\d+\.\d\d) +CPU\)/;
27my $noc_pattern =
28 qr/(\d+) +wallclock secs? +\( *(-?\d+\.\d\d) +usr +\+ +(-?\d+\.\d\d) +sys += +(-?\d+\.\d\d) +CPU\)/;
29my $nop_pattern =
30 qr/(\d+) +wallclock secs? +\( *(-?\d+\.\d\d) +cusr +\+ +(-?\d+\.\d\d) +csys += +\d+\.\d\d +CPU\)/;
31# Please don't trust the matching parenthises to be useful in this :-)
32my $default_pattern = qr/$all_pattern|$noc_pattern/;
33
34my $t0 = new Benchmark;
35isa_ok ($t0, 'Benchmark', "Ensure we can create a benchmark object");
36
37# We use the benchmark object once we've done some work:
38
39isa_ok(timeit(5, sub {++$foo}), 'Benchmark', "timeit CODEREF");
40is ($foo, 5, "benchmarked code was run 5 times");
41
42isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
43is ($bar, 5, "benchmarked code was run 5 times");
44
45print "# Burning CPU to benchmark things will take time...\n";
46
47
48
49# We need to do something fairly slow in the coderef.
50# Same coderef. Same place in memory.
51my $coderef = sub {$baz += fib($ballast)};
52
53# The default is three.
54$baz = 0;
55my $threesecs = countit(0, $coderef);
56isa_ok($threesecs, 'Benchmark', "countit 0, CODEREF");
57isnt ($baz, 0, "benchmarked code was run");
58my $in_threesecs = $threesecs->iters;
59print "# $in_threesecs iterations\n";
60ok ($in_threesecs > 0, "iters returned positive iterations");
61
62my $estimate = int ($in_threesecs / 3);
63print "# from the 3 second run estimate $estimate iterations in 1 second...\n";
64$baz = 0;
65my $onesec = countit(1, $coderef);
66isa_ok($onesec, 'Benchmark', "countit 1, CODEREF");
67isnt ($baz, 0, "benchmarked code was run");
68my $in_onesec = $onesec->iters;
69print "# $in_onesec iterations\n";
70ok ($in_onesec > 0, "iters returned positive iterations");
71
72my $difference = $in_onesec - $estimate;
73ok (abs ($difference / $in_onesec) < $delta,
74 "is $in_onesec within $delta of estimate ($estimate)");
75
76# I found that the eval'ed version was 3 times faster than the coderef.
77# (now it has a different ballast value)
78$baz = 0;
79my $again = countit(1, '$baz += fib($ballast)');
80isa_ok($onesec, 'Benchmark', "countit 1, eval");
81isnt ($baz, 0, "benchmarked code was run");
82my $in_again = $again->iters;
83print "# $in_again iterations\n";
84ok ($in_again > 0, "iters returned positive iterations");
85
86
87my $t1 = new Benchmark;
88isa_ok ($t1, 'Benchmark', "Create another benchmark object now we're finished");
89
90my $diff = timediff ($t1, $t0);
91isa_ok ($diff, 'Benchmark', "Get the time difference");
92isa_ok (timesum ($t0, $t1), 'Benchmark', "check timesum");
93
94my $default = timestr ($diff);
95isnt ($default, '', 'timestr ($diff)');
96my $auto = timestr ($diff, 'auto');
97is ($auto, $default, 'timestr ($diff, "auto") matches timestr ($diff)');
98
99{
100 my $all = timestr ($diff, 'all');
101 like ($all, $all_pattern, 'timestr ($diff, "all")');
102 print "# $all\n";
103
104 my ($wallclock, $usr, $sys, $cusr, $csys, $cpu) = $all =~ $all_pattern;
105
106 is (timestr ($diff, 'none'), '', "none supresses output");
107
108 my $noc = timestr ($diff, 'noc');
109 like ($noc, qr/$wallclock +wallclock secs? +\( *$usr +usr +\+ +$sys +sys += +$cpu +CPU\)/, 'timestr ($diff, "noc")');
110
111 my $nop = timestr ($diff, 'nop');
112 like ($nop, qr/$wallclock +wallclock secs? +\( *$cusr +cusr +\+ +$csys +csys += +\d+\.\d\d +CPU\)/, 'timestr ($diff, "nop")');
113
114 if ($auto eq $noc) {
115 pass ('"auto" is "noc"');
116 } else {
117 is ($auto, $all, '"auto" isn\'t "noc", so should be eq to "all"');
118 }
119
120 like (timestr ($diff, 'all', 'E'),
121 qr/(\d+) +wallclock secs? +\( *\d\.\d+E[-+]?\d\d\d? +usr +\d\.\d+E[-+]?\d\d\d? +sys +\+ +\d\.\d+E[-+]?\d\d\d? +cusr +\d\.\d+E[-+]?\d\d\d? +csys += +\d\.\d+E[-+]?\d\d\d? +CPU\)/, 'timestr ($diff, "all", "E") [sprintf format of "E"]');
122}
123
124my $out = tie *OUT, 'TieOut';
125
126my $iterations = 3;
127
128$foo = 0;
129select(OUT);
130my $got = timethis($iterations, sub {++$foo});
131select(STDOUT);
132isa_ok($got, 'Benchmark', "timethis CODEREF");
133is ($foo, $iterations, "benchmarked code was run $iterations times");
134
135$got = $out->read();
136like ($got, qr/^timethis $iterations/, 'default title');
137like ($got, $default_pattern, 'default format is all or noc');
138
139$bar = 0;
140select(OUT);
141$got = timethis($iterations, '++$bar');
142select(STDOUT);
143isa_ok($got, 'Benchmark', "timethis eval");
144is ($bar, $iterations, "benchmarked code was run $iterations times");
145
146$got = $out->read();
147like ($got, qr/^timethis $iterations/, 'default title');
148like ($got, $default_pattern, 'default format is all or noc');
149
150my $title = 'lies, damn lies and benchmarks';
151$foo = 0;
152select(OUT);
153$got = timethis($iterations, sub {++$foo}, $title);
154select(STDOUT);
155isa_ok($got, 'Benchmark', "timethis with title");
156is ($foo, $iterations, "benchmarked code was run $iterations times");
157
158$got = $out->read();
159like ($got, qr/^$title:/, 'specify title');
160like ($got, $default_pattern, 'default format is all or noc');
161
162# default is auto, which is all or noc. nop can never match the default
163$foo = 0;
164select(OUT);
165$got = timethis($iterations, sub {++$foo}, $title, 'nop');
166select(STDOUT);
167isa_ok($got, 'Benchmark', "timethis with format");
168is ($foo, $iterations, "benchmarked code was run $iterations times");
169
170$got = $out->read();
171like ($got, qr/^$title:/, 'specify title');
172like ($got, $nop_pattern, 'specify format as nop');
173
174{
175 $foo = 0;
176 select(OUT);
177 my $start = time;
178 $got = timethis(-2, sub {$foo+= fib($ballast)}, $title, 'none');
179 my $end = time;
180 select(STDOUT);
181 isa_ok($got, 'Benchmark',
182 "timethis, at least 2 seconds with format 'none'");
183 ok ($foo > 0, "benchmarked code was run");
184 ok ($end - $start > 1, "benchmarked code ran for over 1 second");
185
186 $got = $out->read();
187 # Remove any warnings about having too few iterations.
188 $got =~ s/\(warning:[^\)]+\)//gs;
189 $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning
190
191 is ($got, '', "format 'none' should suppress output");
192}
193
194$foo = $bar = $baz = 0;
195select(OUT);
196$got = timethese($iterations, { Foo => sub {++$foo}, Bar => '++$bar',
197 Baz => sub {++$baz} });
198select(STDOUT);
199is(ref ($got), 'HASH', "timethese should return a hashref");
200isa_ok($got->{Foo}, 'Benchmark', "Foo value");
201isa_ok($got->{Bar}, 'Benchmark', "Bar value");
202isa_ok($got->{Baz}, 'Benchmark', "Baz value");
203eq_set([keys %$got], [qw(Foo Bar Baz)], 'should be exactly three objects');
204is ($foo, $iterations, "Foo code was run $iterations times");
205is ($bar, $iterations, "Bar code was run $iterations times");
206is ($baz, $iterations, "Baz code was run $iterations times");
207
208$got = $out->read();
209# Remove any warnings about having too few iterations.
210$got =~ s/\(warning:[^\)]+\)//gs;
211
212like ($got, qr/timing $iterations iterations of\s+Bar\W+Baz\W+Foo\W*?\.\.\./s,
213 'check title');
214# Remove the title
215$got =~ s/.*\.\.\.//s;
216like ($got, qr/\bBar\b.*\bBaz\b.*\bFoo\b/s, 'check output is in sorted order');
217like ($got, $default_pattern, 'should find default format somewhere');
218
219my $code_to_test = { Foo => sub {$foo+=fib($ballast-2)},
220 Bar => sub {$bar+=fib($ballast)}};
221# Keep these for later.
222my $results;
223{
224 $foo = $bar = 0;
225 select(OUT);
226 my $start = times;
227 $results = timethese(-0.1, $code_to_test, 'none');
228 my $end = times;
229 select(STDOUT);
230
231 is(ref ($results), 'HASH', "timethese should return a hashref");
232 isa_ok($results->{Foo}, 'Benchmark', "Foo value");
233 isa_ok($results->{Bar}, 'Benchmark', "Bar value");
234 eq_set([keys %$results], [qw(Foo Bar)], 'should be exactly two objects');
235 ok ($foo > 0, "Foo code was run");
236 ok ($bar > 0, "Bar code was run");
237
238 ok (($end - $start) > 0.1, "benchmarked code ran for over 0.1 seconds");
239
240 $got = $out->read();
241 # Remove any warnings about having too few iterations.
242 $got =~ s/\(warning:[^\)]+\)//gs;
243 is ($got =~ tr/ \t\n//c, 0, "format 'none' should suppress output");
244}
245my $graph_dissassembly =
246 qr!^[ \t]+(\S+)[ \t]+(\w+)[ \t]+(\w+)[ \t]* # Title line
247 \n[ \t]*(\w+)[ \t]+([0-9.]+(?:/s)?)[ \t]+(-+)[ \t]+(-?\d+%)[ \t]*
248 \n[ \t]*(\w+)[ \t]+([0-9.]+(?:/s)?)[ \t]+(-?\d+%)[ \t]+(-+)[ \t]*$!xm;
249
250sub check_graph_consistency {
251 my ( $ratetext, $slowc, $fastc,
252 $slowr, $slowratet, $slowslow, $slowfastt,
253 $fastr, $fastratet, $fastslowt, $fastfast)
254 = @_;
255 is ($slowc, $slowr, "left col tag should be top row tag");
256 is ($fastc, $fastr, "right col tag should be bottom row tag");
257 like ($slowslow, qr/^-+/, "should be dash for comparing slow with slow");
258 is ($slowslow, $fastfast, "slow v slow should be same as fast v fast");
259 my $slowrate = $slowratet;
260 my $fastrate = $fastratet;
261 my ($slow_is_rate, $fast_is_rate);
262 unless ($slow_is_rate = $slowrate =~ s!/s!!) {
263 # Slow is expressed as iters per second.
264 $slowrate = 1/$slowrate if $slowrate;
265 }
266 unless ($fast_is_rate = $fastrate =~ s!/s!!) {
267 # Fast is expressed as iters per second.
268 $fastrate = 1/$fastrate if $fastrate;
269 }
270 if ($ratetext =~ /rate/i) {
271 ok ($slow_is_rate, "slow should be expressed as a rate");
272 ok ($fast_is_rate, "fast should be expressed as a rate");
273 } else {
274 ok (!$slow_is_rate, "slow should be expressed as a iters per second");
275 ok (!$fast_is_rate, "fast should be expressed as a iters per second");
276 }
277
278 (my $slowfast = $slowfastt) =~ s!%!!;
279 (my $fastslow = $fastslowt) =~ s!%!!;
280 if ($slowrate < $fastrate) {
281 pass ("slow rate is less than fast rate");
282 ok ($slowfast < 0 && $slowfast > -100,
283 "slowfast should be less than zero, and > -100");
284 ok ($fastslow > 100, "fastslow should be > 100");
285 } else {
286 is ($slowrate, $fastrate,
287 "slow rate isn't less than fast rate, so should be the same");
288 is ($slowfast, 0, "slowfast should be zero");
289 is ($fastslow, 0, "fastslow should be zero");
290 }
291}
292
293sub check_graph_vs_output {
294 my ($chart, $got) = @_;
295 my ( $ratetext, $slowc, $fastc,
296 $slowr, $slowratet, $slowslow, $slowfastt,
297 $fastr, $fastratet, $fastslowt, $fastfast)
298 = $got =~ $graph_dissassembly;
299 check_graph_consistency ( $ratetext, $slowc, $fastc,
300 $slowr, $slowratet, $slowslow, $slowfastt,
301 $fastr, $fastratet, $fastslowt, $fastfast);
302 is_deeply ($chart, [['', $ratetext, $slowc, $fastc],
303 [$slowr, $slowratet, $slowslow, $slowfastt],
304 [$fastr, $fastratet, $fastslowt, $fastfast]],
305 "check the chart layout matches the formatted output");
306}
307
308sub check_graph {
309 my ($title, $row1, $row2) = @_;
310 is (scalar @$title, 4, "Four entries in title row");
311 is (scalar @$row1, 4, "Four entries in first row");
312 is (scalar @$row2, 4, "Four entries in second row");
313 is (shift @$title, '', "First entry of output graph should be ''");
314 check_graph_consistency (@$title, @$row1, @$row2);
315}
316
317{
318 select(OUT);
319 my $start = times;
320 my $chart = cmpthese( -0.1, { a => "++\$i", b => "\$i *= 2" } ) ;
321 my $end = times;
322 select(STDOUT);
323 ok (($end - $start) > 0.05, "benchmarked code ran for over 0.05 seconds");
324
325 $got = $out->read();
326 # Remove any warnings about having too few iterations.
327 $got =~ s/\(warning:[^\)]+\)//gs;
328
329 like ($got, qr/running\W+a\W+b.*?for at least 0\.1 CPU second/s,
330 'check title');
331 # Remove the title
332 $got =~ s/.*\.\.\.//s;
333 like ($got, $default_pattern, 'should find default format somewhere');
334 like ($got, $graph_dissassembly, "Should find the output graph somewhere");
335 check_graph_vs_output ($chart, $got);
336}
337
338{
339 $foo = $bar = 0;
340 select(OUT);
341 my $chart = cmpthese( 10, $code_to_test, 'nop' ) ;
342 select(STDOUT);
343 ok ($foo > 0, "Foo code was run");
344 ok ($bar > 0, "Bar code was run");
345
346 $got = $out->read();
347 # Remove any warnings about having too few iterations.
348 $got =~ s/\(warning:[^\)]+\)//gs;
349 like ($got, qr/timing 10 iterations of\s+Bar\W+Foo\W*?\.\.\./s,
350 'check title');
351 # Remove the title
352 $got =~ s/.*\.\.\.//s;
353 like ($got, $nop_pattern, 'specify format as nop');
354 like ($got, $graph_dissassembly, "Should find the output graph somewhere");
355 check_graph_vs_output ($chart, $got);
356}
357
358{
359 $foo = $bar = 0;
360 select(OUT);
361 my $chart = cmpthese( 10, $code_to_test, 'none' ) ;
362 select(STDOUT);
363 ok ($foo > 0, "Foo code was run");
364 ok ($bar > 0, "Bar code was run");
365
366 $got = $out->read();
367 # Remove any warnings about having too few iterations.
368 $got =~ s/\(warning:[^\)]+\)//gs;
369 $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning
370 is ($got, '', "format 'none' should suppress output");
371 is (ref $chart, 'ARRAY', "output should be an array ref");
372 # Some of these will go bang if the preceding test fails. There will be
373 # a big clue as to why, from the previous test's diagnostic
374 is (ref $chart->[0], 'ARRAY', "output should be an array of arrays");
375 check_graph (@$chart);
376}
377
378{
379 $foo = $bar = 0;
380 select(OUT);
381 my $chart = cmpthese( $results ) ;
382 select(STDOUT);
383 is ($foo, 0, "Foo code was not run");
384 is ($bar, 0, "Bar code was not run");
385
386 $got = $out->read();
387 ok ($got !~ /\.\.\./s, 'check that there is no title');
388 like ($got, $graph_dissassembly, "Should find the output graph somewhere");
389 check_graph_vs_output ($chart, $got);
390}
391
392{
393 $foo = $bar = 0;
394 select(OUT);
395 my $chart = cmpthese( $results, 'none' ) ;
396 select(STDOUT);
397 is ($foo, 0, "Foo code was not run");
398 is ($bar, 0, "Bar code was not run");
399
400 $got = $out->read();
401 is ($got, '', "'none' should suppress all output");
402 is (ref $chart, 'ARRAY', "output should be an array ref");
403 # Some of these will go bang if the preceding test fails. There will be
404 # a big clue as to why, from the previous test's diagnostic
405 is (ref $chart->[0], 'ARRAY', "output should be an array of arrays");
406 check_graph (@$chart);
407}
408
409###}my $out = tie *OUT, 'TieOut'; my ($got); ###
410
411my $debug = tie *STDERR, 'TieOut';
412
413$bar = 0;
414isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
415is ($bar, 5, "benchmarked code was run 5 times");
416is ($debug->read(), '', "There was no debug output");
417
418Benchmark->debug(1);
419
420$bar = 0;
421select(OUT);
422$got = timeit(5, '++$bar');
423select(STDOUT);
424isa_ok($got, 'Benchmark', "timeit eval");
425is ($bar, 5, "benchmarked code was run 5 times");
426is ($out->read(), '', "There was no STDOUT output with debug enabled");
427isnt ($debug->read(), '', "There was STDERR debug output with debug enabled");
428
429Benchmark->debug(0);
430
431$bar = 0;
432isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
433is ($bar, 5, "benchmarked code was run 5 times");
434is ($debug->read(), '', "There was no debug output debug disabled");
435
436undef $debug;
437untie *STDERR;
438
439# To check the cache we are poking where we don't belong, inside the namespace.
440# The way benchmark is written We can't actually check whehter the cache is
441# being used, merely what's become cached.
442
443clearallcache();
444my @before_keys = keys %Benchmark::cache;
445$bar = 0;
446isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
447is ($bar, 5, "benchmarked code was run 5 times");
448my @after5_keys = keys %Benchmark::cache;
449$bar = 0;
450isa_ok(timeit(10, '++$bar'), 'Benchmark', "timeit eval");
451is ($bar, 10, "benchmarked code was run 10 times");
452ok (!eq_array ([keys %Benchmark::cache], \@after5_keys), "10 differs from 5");
453
454clearcache(10);
455# Hash key order will be the same if there are the same keys.
456is_deeply ([keys %Benchmark::cache], \@after5_keys,
457 "cleared 10, only cached results for 5 should remain");
458
459clearallcache();
460is_deeply ([keys %Benchmark::cache], \@before_keys,
461 "back to square 1 when we clear the cache again?");
462
463
464package TieOut;
465
466sub TIEHANDLE {
467 my $class = shift;
468 bless(\( my $ref = ''), $class);
469}
470
471sub PRINT {
472 my $self = shift;
473 $$self .= join('', @_);
474}
475
476sub PRINTF {
477 my $self = shift;
478 $$self .= sprintf shift, @_;
479}
480
481sub read {
482 my $self = shift;
483 return substr($$self, 0, length($$self), '');
484}