Win32 pacifying from mjd.
[perl.git] / lib / Benchmark.t
1 #!./perl -w
2
3 BEGIN {
4     chdir 't' if -d 't';
5     @INC = '../lib';
6 }
7
8 use warnings;
9 use strict;
10 use vars qw($foo $bar $baz $ballast);
11 use Test::More tests => 159;
12
13 use Benchmark qw(:all);
14
15 my $delta = 0.3;
16
17 # Some timing ballast
18 sub fib {
19   my $n = shift;
20   return $n if $n < 2;
21   fib($n-1) + fib($n-2);
22 }
23 $ballast = 15;
24
25 my $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\)/;
27 my $noc_pattern =
28     qr/(\d+) +wallclock secs? +\( *(-?\d+\.\d\d) +usr +\+ +(-?\d+\.\d\d) +sys += +(-?\d+\.\d\d) +CPU\)/;
29 my $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 :-)
32 my $default_pattern = qr/$all_pattern|$noc_pattern/;
33
34 my $t0 = new Benchmark;
35 isa_ok ($t0, 'Benchmark', "Ensure we can create a benchmark object");
36
37 # We use the benchmark object once we've done some work:
38
39 isa_ok(timeit(5, sub {++$foo}), 'Benchmark', "timeit CODEREF");
40 is ($foo, 5, "benchmarked code was run 5 times");
41
42 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
43 is ($bar, 5, "benchmarked code was run 5 times");
44
45 print "# 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.
51 my $coderef = sub {$baz += fib($ballast)};
52
53 # The default is three.
54 $baz = 0;
55 my $threesecs = countit(0, $coderef);
56 isa_ok($threesecs, 'Benchmark', "countit 0, CODEREF");
57 isnt ($baz, 0, "benchmarked code was run");
58 my $in_threesecs = $threesecs->iters;
59 print "# $in_threesecs iterations\n";
60 ok ($in_threesecs > 0, "iters returned positive iterations");
61
62 my $estimate = int (100 * $in_threesecs / 3) / 100;
63 print "# from the 3 second run estimate $estimate iterations in 1 second...\n";
64 $baz = 0;
65 my $onesec = countit(1, $coderef);
66 isa_ok($onesec, 'Benchmark', "countit 1, CODEREF");
67 isnt ($baz, 0, "benchmarked code was run");
68 my $in_onesec = $onesec->iters;
69 print "# $in_onesec iterations\n";
70 ok ($in_onesec > 0, "iters returned positive iterations");
71
72 my $difference = $in_onesec - $estimate;
73 ok (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;
79 my $again = countit(1, '$baz += fib($ballast)');
80 isa_ok($onesec, 'Benchmark', "countit 1, eval");
81 isnt ($baz, 0, "benchmarked code was run");
82 my $in_again = $again->iters;
83 print "# $in_again iterations\n";
84 ok ($in_again > 0, "iters returned positive iterations");
85
86
87 my $t1 = new Benchmark;
88 isa_ok ($t1, 'Benchmark', "Create another benchmark object now we're finished");
89
90 my $diff = timediff ($t1, $t0);
91 isa_ok ($diff, 'Benchmark', "Get the time difference");
92 isa_ok (timesum ($t0, $t1), 'Benchmark', "check timesum");
93
94 my $default = timestr ($diff);
95 isnt ($default, '', 'timestr ($diff)');
96 my $auto = timestr ($diff, 'auto');
97 is ($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
124 my $out = tie *OUT, 'TieOut';
125
126 my $iterations = 3;
127
128 $foo = 0;
129 select(OUT);
130 my $got = timethis($iterations, sub {++$foo});
131 select(STDOUT);
132 isa_ok($got, 'Benchmark', "timethis CODEREF");
133 is ($foo, $iterations, "benchmarked code was run $iterations times");
134
135 $got = $out->read();
136 like ($got, qr/^timethis $iterations/, 'default title');
137 like ($got, $default_pattern, 'default format is all or noc');
138
139 $bar = 0;
140 select(OUT);
141 $got = timethis($iterations, '++$bar');
142 select(STDOUT);
143 isa_ok($got, 'Benchmark', "timethis eval");
144 is ($bar, $iterations, "benchmarked code was run $iterations times");
145
146 $got = $out->read();
147 like ($got, qr/^timethis $iterations/, 'default title');
148 like ($got, $default_pattern, 'default format is all or noc');
149
150 my $title = 'lies, damn lies and benchmarks';
151 $foo = 0;
152 select(OUT);
153 $got = timethis($iterations, sub {++$foo}, $title);
154 select(STDOUT);
155 isa_ok($got, 'Benchmark', "timethis with title");
156 is ($foo, $iterations, "benchmarked code was run $iterations times");
157
158 $got = $out->read();
159 like ($got, qr/^$title:/, 'specify title');
160 like ($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;
164 select(OUT);
165 $got = timethis($iterations, sub {++$foo}, $title, 'nop');
166 select(STDOUT);
167 isa_ok($got, 'Benchmark', "timethis with format");
168 is ($foo, $iterations, "benchmarked code was run $iterations times");
169
170 $got = $out->read();
171 like ($got, qr/^$title:/, 'specify title');
172 like ($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;
195 select(OUT);
196 $got = timethese($iterations, { Foo => sub {++$foo}, Bar => '++$bar',
197                                 Baz => sub {++$baz} });
198 select(STDOUT);
199 is(ref ($got), 'HASH', "timethese should return a hashref");
200 isa_ok($got->{Foo}, 'Benchmark', "Foo value");
201 isa_ok($got->{Bar}, 'Benchmark', "Bar value");
202 isa_ok($got->{Baz}, 'Benchmark', "Baz value");
203 eq_set([keys %$got], [qw(Foo Bar Baz)], 'should be exactly three objects');
204 is ($foo, $iterations, "Foo code was run $iterations times");
205 is ($bar, $iterations, "Bar code was run $iterations times");
206 is ($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
212 like ($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;
216 like ($got, qr/\bBar\b.*\bBaz\b.*\bFoo\b/s, 'check output is in sorted order');
217 like ($got, $default_pattern, 'should find default format somewhere');
218
219 my $code_to_test =  { Foo => sub {$foo+=fib($ballast-2)},
220                       Bar => sub {$bar+=fib($ballast)}};
221 # Keep these for later.
222 my $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 }
245 my $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
250 sub 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           print STDERR "# slowfast $slowfast\n";
285         ok ($fastslow > 0, "fastslow should be > 0") ||
286           print STDERR "# fastslow $fastslow\n";
287     } else {
288         is ($slowrate, $fastrate,
289             "slow rate isn't less than fast rate, so should be the same");
290         is ($slowfast, 0, "slowfast should be zero");
291         is ($fastslow, 0, "fastslow should be zero");
292     }
293 }
294
295 sub check_graph_vs_output {
296     my ($chart, $got) = @_;
297     my (        $ratetext, $slowc, $fastc,
298         $slowr, $slowratet, $slowslow, $slowfastt,
299         $fastr, $fastratet, $fastslowt, $fastfast)
300         = $got =~ $graph_dissassembly;
301     check_graph_consistency (        $ratetext, $slowc, $fastc,
302                              $slowr, $slowratet, $slowslow, $slowfastt,
303                              $fastr, $fastratet, $fastslowt, $fastfast);
304     is_deeply ($chart, [['', $ratetext, $slowc, $fastc],
305                         [$slowr, $slowratet, $slowslow, $slowfastt],
306                         [$fastr, $fastratet, $fastslowt, $fastfast]],
307                "check the chart layout matches the formatted output");
308 }
309
310 sub check_graph {
311     my ($title, $row1, $row2) = @_;
312     is (scalar @$title, 4, "Four entries in title row");
313     is (scalar @$row1, 4, "Four entries in first row");
314     is (scalar @$row2, 4, "Four entries in second row");
315     is (shift @$title, '', "First entry of output graph should be ''");
316     check_graph_consistency (@$title, @$row1, @$row2);
317 }
318
319 {
320     select(OUT);
321     my $start = times;
322     my $chart = cmpthese( -0.1, { a => "++\$i", b => "\$i = sqrt(\$i++)" } ) ;
323     my $end = times;
324     select(STDOUT);
325     ok (($end - $start) > 0.05, "benchmarked code ran for over 0.05 seconds");
326
327     $got = $out->read();
328     # Remove any warnings about having too few iterations.
329     $got =~ s/\(warning:[^\)]+\)//gs;
330
331     like ($got, qr/running\W+a\W+b.*?for at least 0\.1 CPU second/s,
332           'check title');
333     # Remove the title
334     $got =~ s/.*\.\.\.//s;
335     like ($got, $default_pattern, 'should find default format somewhere');
336     like ($got, $graph_dissassembly, "Should find the output graph somewhere");
337     check_graph_vs_output ($chart, $got);
338 }
339
340 {
341     $foo = $bar = 0;
342     select(OUT);
343     my $chart = cmpthese( 10, $code_to_test, 'nop' ) ;
344     select(STDOUT);
345     ok ($foo > 0, "Foo code was run");
346     ok ($bar > 0, "Bar code was run");
347
348     $got = $out->read();
349     # Remove any warnings about having too few iterations.
350     $got =~ s/\(warning:[^\)]+\)//gs;
351     like ($got, qr/timing 10 iterations of\s+Bar\W+Foo\W*?\.\.\./s,
352       'check title');
353     # Remove the title
354     $got =~ s/.*\.\.\.//s;
355     like ($got, $nop_pattern, 'specify format as nop');
356     like ($got, $graph_dissassembly, "Should find the output graph somewhere");
357     check_graph_vs_output ($chart, $got);
358 }
359
360 {
361     $foo = $bar = 0;
362     select(OUT);
363     my $chart = cmpthese( 10, $code_to_test, 'none' ) ;
364     select(STDOUT);
365     ok ($foo > 0, "Foo code was run");
366     ok ($bar > 0, "Bar code was run");
367
368     $got = $out->read();
369     # Remove any warnings about having too few iterations.
370     $got =~ s/\(warning:[^\)]+\)//gs;
371     $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning
372     is ($got, '', "format 'none' should suppress output");
373     is (ref $chart, 'ARRAY', "output should be an array ref");
374     # Some of these will go bang if the preceding test fails. There will be
375     # a big clue as to why, from the previous test's diagnostic
376     is (ref $chart->[0], 'ARRAY', "output should be an array of arrays");
377     check_graph (@$chart);
378 }
379
380 {
381     $foo = $bar = 0;
382     select(OUT);
383     my $chart = cmpthese( $results ) ;
384     select(STDOUT);
385     is ($foo, 0, "Foo code was not run");
386     is ($bar, 0, "Bar code was not run");
387
388     $got = $out->read();
389     ok ($got !~ /\.\.\./s, 'check that there is no title');
390     like ($got, $graph_dissassembly, "Should find the output graph somewhere");
391     check_graph_vs_output ($chart, $got);
392 }
393
394 {
395     $foo = $bar = 0;
396     select(OUT);
397     my $chart = cmpthese( $results, 'none' ) ;
398     select(STDOUT);
399     is ($foo, 0, "Foo code was not run");
400     is ($bar, 0, "Bar code was not run");
401
402     $got = $out->read();
403     is ($got, '', "'none' should suppress all output");
404     is (ref $chart, 'ARRAY', "output should be an array ref");
405     # Some of these will go bang if the preceding test fails. There will be
406     # a big clue as to why, from the previous test's diagnostic
407     is (ref $chart->[0], 'ARRAY', "output should be an array of arrays");
408     check_graph (@$chart);
409 }
410
411 ###}my $out = tie *OUT, 'TieOut'; my ($got); ###
412
413 my $debug = tie *STDERR, 'TieOut';
414
415 $bar = 0;
416 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
417 is ($bar, 5, "benchmarked code was run 5 times");
418 is ($debug->read(), '', "There was no debug output");
419
420 Benchmark->debug(1);
421
422 $bar = 0;
423 select(OUT);
424 $got = timeit(5, '++$bar');
425 select(STDOUT);
426 isa_ok($got, 'Benchmark', "timeit eval");
427 is ($bar, 5, "benchmarked code was run 5 times");
428 is ($out->read(), '', "There was no STDOUT output with debug enabled");
429 isnt ($debug->read(), '', "There was STDERR debug output with debug enabled");
430
431 Benchmark->debug(0);
432
433 $bar = 0;
434 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
435 is ($bar, 5, "benchmarked code was run 5 times");
436 is ($debug->read(), '', "There was no debug output debug disabled");
437
438 undef $debug;
439 untie *STDERR;
440
441 # To check the cache we are poking where we don't belong, inside the namespace.
442 # The way benchmark is written We can't actually check whehter the cache is
443 # being used, merely what's become cached.
444
445 clearallcache();
446 my @before_keys = keys %Benchmark::cache;
447 $bar = 0;
448 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
449 is ($bar, 5, "benchmarked code was run 5 times");
450 my @after5_keys = keys %Benchmark::cache;
451 $bar = 0;
452 isa_ok(timeit(10, '++$bar'), 'Benchmark', "timeit eval");
453 is ($bar, 10, "benchmarked code was run 10 times");
454 ok (!eq_array ([keys %Benchmark::cache], \@after5_keys), "10 differs from 5");
455
456 clearcache(10);
457 # Hash key order will be the same if there are the same keys.
458 is_deeply ([keys %Benchmark::cache], \@after5_keys,
459            "cleared 10, only cached results for 5 should remain");
460
461 clearallcache();
462 is_deeply ([keys %Benchmark::cache], \@before_keys,
463            "back to square 1 when we clear the cache again?");
464
465
466 package TieOut;
467
468 sub TIEHANDLE {
469     my $class = shift;
470     bless(\( my $ref = ''), $class);
471 }
472
473 sub PRINT {
474     my $self = shift;
475     $$self .= join('', @_);
476 }
477
478 sub PRINTF {
479     my $self = shift;
480     $$self .= sprintf shift, @_;
481 }
482
483 sub read {
484     my $self = shift;
485     return substr($$self, 0, length($$self), '');
486 }