10 use vars qw($foo $bar $baz $ballast);
11 use Test::More tests => 193;
13 use Benchmark qw(:all);
21 fib($n-1) + fib($n-2);
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\)/;
28 qr/(\d+) +wallclock secs? +\( *(-?\d+\.\d\d) +usr +\+ +(-?\d+\.\d\d) +sys += +(-?\d+\.\d\d) +CPU\)/;
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/;
34 my $t0 = new Benchmark;
35 isa_ok ($t0, 'Benchmark', "Ensure we can create a benchmark object");
37 # We use the benchmark object once we've done some work:
39 isa_ok(timeit(5, sub {++$foo}), 'Benchmark', "timeit CODEREF");
40 is ($foo, 5, "benchmarked code was run 5 times");
42 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
43 is ($bar, 5, "benchmarked code was run 5 times");
45 print "# Burning CPU to benchmark things will take time...\n";
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)};
53 # The default is three.
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");
62 my $estimate = int (100 * $in_threesecs / 3) / 100;
63 print "# from the 3 second run estimate $estimate iterations in 1 second...\n";
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");
73 my $difference = $in_onesec - $estimate;
74 my $actual = abs ($difference / $in_onesec);
75 ok ($actual < $delta, "is $in_onesec within $delta of estimate ($estimate)");
76 print "# $in_onesec is between " . ($delta / 2) .
77 " and $delta of estimate. Not that safe.\n" if $actual > $delta/2;
80 # I found that the eval'ed version was 3 times faster than the coderef.
81 # (now it has a different ballast value)
83 my $again = countit(1, '$baz += fib($ballast)');
84 isa_ok($onesec, 'Benchmark', "countit 1, eval");
85 isnt ($baz, 0, "benchmarked code was run");
86 my $in_again = $again->iters;
87 print "# $in_again iterations\n";
88 ok ($in_again > 0, "iters returned positive iterations");
91 my $t1 = new Benchmark;
92 isa_ok ($t1, 'Benchmark', "Create another benchmark object now we're finished");
94 my $diff = timediff ($t1, $t0);
95 isa_ok ($diff, 'Benchmark', "Get the time difference");
96 isa_ok (timesum ($t0, $t1), 'Benchmark', "check timesum");
98 my $default = timestr ($diff);
99 isnt ($default, '', 'timestr ($diff)');
100 my $auto = timestr ($diff, 'auto');
101 is ($auto, $default, 'timestr ($diff, "auto") matches timestr ($diff)');
104 my $all = timestr ($diff, 'all');
105 like ($all, $All_Pattern, 'timestr ($diff, "all")');
108 my ($wallclock, $usr, $sys, $cusr, $csys, $cpu) = $all =~ $All_Pattern;
110 is (timestr ($diff, 'none'), '', "none supresses output");
112 my $noc = timestr ($diff, 'noc');
113 like ($noc, qr/$wallclock +wallclock secs? +\( *$usr +usr +\+ +$sys +sys += +$cpu +CPU\)/, 'timestr ($diff, "noc")');
115 my $nop = timestr ($diff, 'nop');
116 like ($nop, qr/$wallclock +wallclock secs? +\( *$cusr +cusr +\+ +$csys +csys += +\d+\.\d\d +CPU\)/, 'timestr ($diff, "nop")');
119 pass ('"auto" is "noc"');
121 is ($auto, $all, '"auto" isn\'t "noc", so should be eq to "all"');
124 like (timestr ($diff, 'all', 'E'),
125 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"]');
128 my $out = tie *OUT, 'TieOut';
134 my $got = timethis($iterations, sub {++$foo});
136 isa_ok($got, 'Benchmark', "timethis CODEREF");
137 is ($foo, $iterations, "benchmarked code was run $iterations times");
140 like ($got, qr/^timethis $iterations/, 'default title');
141 like ($got, $Default_Pattern, 'default format is all or noc');
145 $got = timethis($iterations, '++$bar');
147 isa_ok($got, 'Benchmark', "timethis eval");
148 is ($bar, $iterations, "benchmarked code was run $iterations times");
151 like ($got, qr/^timethis $iterations/, 'default title');
152 like ($got, $Default_Pattern, 'default format is all or noc');
154 my $title = 'lies, damn lies and benchmarks';
157 $got = timethis($iterations, sub {++$foo}, $title);
159 isa_ok($got, 'Benchmark', "timethis with title");
160 is ($foo, $iterations, "benchmarked code was run $iterations times");
163 like ($got, qr/^$title:/, 'specify title');
164 like ($got, $Default_Pattern, 'default format is all or noc');
166 # default is auto, which is all or noc. nop can never match the default
169 $got = timethis($iterations, sub {++$foo}, $title, 'nop');
171 isa_ok($got, 'Benchmark', "timethis with format");
172 is ($foo, $iterations, "benchmarked code was run $iterations times");
175 like ($got, qr/^$title:/, 'specify title');
176 like ($got, $Nop_Pattern, 'specify format as nop');
182 $got = timethis(-2, sub {$foo+= fib($ballast)}, $title, 'none');
185 isa_ok($got, 'Benchmark',
186 "timethis, at least 2 seconds with format 'none'");
187 ok ($foo > 0, "benchmarked code was run");
188 ok ($end - $start > 1, "benchmarked code ran for over 1 second");
191 # Remove any warnings about having too few iterations.
192 $got =~ s/\(warning:[^\)]+\)//gs;
193 $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning
195 is ($got, '', "format 'none' should suppress output");
198 $foo = $bar = $baz = 0;
200 $got = timethese($iterations, { Foo => sub {++$foo}, Bar => '++$bar',
201 Baz => sub {++$baz} });
203 is(ref ($got), 'HASH', "timethese should return a hashref");
204 isa_ok($got->{Foo}, 'Benchmark', "Foo value");
205 isa_ok($got->{Bar}, 'Benchmark', "Bar value");
206 isa_ok($got->{Baz}, 'Benchmark', "Baz value");
207 eq_set([keys %$got], [qw(Foo Bar Baz)], 'should be exactly three objects');
208 is ($foo, $iterations, "Foo code was run $iterations times");
209 is ($bar, $iterations, "Bar code was run $iterations times");
210 is ($baz, $iterations, "Baz code was run $iterations times");
213 # Remove any warnings about having too few iterations.
214 $got =~ s/\(warning:[^\)]+\)//gs;
216 like ($got, qr/timing $iterations iterations of\s+Bar\W+Baz\W+Foo\W*?\.\.\./s,
219 $got =~ s/.*\.\.\.//s;
220 like ($got, qr/\bBar\b.*\bBaz\b.*\bFoo\b/s, 'check output is in sorted order');
221 like ($got, $Default_Pattern, 'should find default format somewhere');
224 { # ensure 'use strict' does not leak from Benchmark.pm into benchmarked code
230 { undeclared_var => q{ $i++; $i-- },
231 symbolic_ref => q{ $bar = 42;
239 is( $@, '', q{no strict leakage in name => 'code'} );
243 { undeclared_var => sub { $i++; $i-- },
244 symbolic_ref => sub { $bar = 42;
251 is( $@, '', q{no strict leakage in name => sub { code }} );
258 my $code_to_test = { Foo => sub {$foo+=fib($ballast-2)},
259 Bar => sub {$bar+=fib($ballast)}};
260 # Keep these for later.
266 $results = timethese(-0.1, $code_to_test, 'none');
270 is(ref ($results), 'HASH', "timethese should return a hashref");
271 isa_ok($results->{Foo}, 'Benchmark', "Foo value");
272 isa_ok($results->{Bar}, 'Benchmark', "Bar value");
273 eq_set([keys %$results], [qw(Foo Bar)], 'should be exactly two objects');
274 ok ($foo > 0, "Foo code was run");
275 ok ($bar > 0, "Bar code was run");
277 ok (($end - $start) > 0.1, "benchmarked code ran for over 0.1 seconds");
280 # Remove any warnings about having too few iterations.
281 $got =~ s/\(warning:[^\)]+\)//gs;
282 is ($got =~ tr/ \t\n//c, 0, "format 'none' should suppress output");
284 my $graph_dissassembly =
285 qr!^[ \t]+(\S+)[ \t]+(\w+)[ \t]+(\w+)[ \t]* # Title line
286 \n[ \t]*(\w+)[ \t]+([0-9.]+(?:/s)?)[ \t]+(-+)[ \t]+(-?\d+%)[ \t]*
287 \n[ \t]*(\w+)[ \t]+([0-9.]+(?:/s)?)[ \t]+(-?\d+%)[ \t]+(-+)[ \t]*$!xm;
289 sub check_graph_consistency {
290 my ( $ratetext, $slowc, $fastc,
291 $slowr, $slowratet, $slowslow, $slowfastt,
292 $fastr, $fastratet, $fastslowt, $fastfast)
296 &= is ($slowc, $slowr, "left col tag should be top row tag");
298 &= is ($fastc, $fastr, "right col tag should be bottom row tag");
300 like ($slowslow, qr/^-+/, "should be dash for comparing slow with slow");
302 &= is ($slowslow, $fastfast, "slow v slow should be same as fast v fast");
303 my $slowrate = $slowratet;
304 my $fastrate = $fastratet;
305 my ($slow_is_rate, $fast_is_rate);
306 unless ($slow_is_rate = $slowrate =~ s!/s!!) {
307 # Slow is expressed as iters per second.
308 $slowrate = 1/$slowrate if $slowrate;
310 unless ($fast_is_rate = $fastrate =~ s!/s!!) {
311 # Fast is expressed as iters per second.
312 $fastrate = 1/$fastrate if $fastrate;
314 if ($ratetext =~ /rate/i) {
316 &= ok ($slow_is_rate, "slow should be expressed as a rate");
318 &= ok ($fast_is_rate, "fast should be expressed as a rate");
321 ok (!$slow_is_rate, "slow should be expressed as a iters per second");
323 ok (!$fast_is_rate, "fast should be expressed as a iters per second");
326 (my $slowfast = $slowfastt) =~ s!%!!;
327 (my $fastslow = $fastslowt) =~ s!%!!;
328 if ($slowrate < $fastrate) {
329 pass ("slow rate is less than fast rate");
330 unless (ok ($slowfast <= 0 && $slowfast >= -100,
331 "slowfast should be less than or equal to zero, and >= -100")) {
332 print STDERR "# slowfast $slowfast\n";
335 unless (ok ($fastslow > 0, "fastslow should be > 0")) {
336 print STDERR "# fastslow $fastslow\n";
341 &= is ($slowrate, $fastrate,
342 "slow rate isn't less than fast rate, so should be the same");
343 # In OpenBSD the $slowfast is sometimes a really, really, really
344 # small number less than zero, and this gets stringified as -0.
346 &= like ($slowfast, qr/^-?0$/, "slowfast should be zero");
348 &= like ($fastslow, qr/^-?0$/, "fastslow should be zero");
353 sub check_graph_vs_output {
354 my ($chart, $got) = @_;
355 my ( $ratetext, $slowc, $fastc,
356 $slowr, $slowratet, $slowslow, $slowfastt,
357 $fastr, $fastratet, $fastslowt, $fastfast)
358 = $got =~ $graph_dissassembly;
360 = check_graph_consistency ( $ratetext, $slowc, $fastc,
361 $slowr, $slowratet, $slowslow, $slowfastt,
362 $fastr, $fastratet, $fastslowt, $fastfast);
364 &= is_deeply ($chart, [['', $ratetext, $slowc, $fastc],
365 [$slowr, $slowratet, $slowslow, $slowfastt],
366 [$fastr, $fastratet, $fastslowt, $fastfast]],
367 "check the chart layout matches the formatted output");
368 unless ($all_passed) {
369 print STDERR "# Something went wrong there. I got this chart:\n";
370 print STDERR "# $_\n" foreach split /\n/, $got;
375 my ($title, $row1, $row2) = @_;
376 is (scalar @$title, 4, "Four entries in title row");
377 is (scalar @$row1, 4, "Four entries in first row");
378 is (scalar @$row2, 4, "Four entries in second row");
379 is (shift @$title, '', "First entry of output graph should be ''");
380 check_graph_consistency (@$title, @$row1, @$row2);
386 my $chart = cmpthese( -0.1, { a => "++\$i", b => "\$i = sqrt(\$i++)" }, "auto" ) ;
389 ok (($end - $start) > 0.05, "benchmarked code ran for over 0.05 seconds");
392 # Remove any warnings about having too few iterations.
393 $got =~ s/\(warning:[^\)]+\)//gs;
395 like ($got, qr/running\W+a\W+b.*?for at least 0\.1 CPU second/s,
398 $got =~ s/.*\.\.\.//s;
399 like ($got, $Default_Pattern, 'should find default format somewhere');
400 like ($got, $graph_dissassembly, "Should find the output graph somewhere");
401 check_graph_vs_output ($chart, $got);
404 # Not giving auto should suppress timethese results.
408 my $chart = cmpthese( -0.1, { a => "++\$i", b => "\$i = sqrt(\$i++)" } ) ;
411 ok (($end - $start) > 0.05, "benchmarked code ran for over 0.05 seconds");
414 # Remove any warnings about having too few iterations.
415 $got =~ s/\(warning:[^\)]+\)//gs;
417 unlike ($got, qr/running\W+a\W+b.*?for at least 0\.1 CPU second/s,
418 'should not have title');
420 $got =~ s/.*\.\.\.//s;
421 unlike ($got, $Default_Pattern, 'should not find default format somewhere');
422 like ($got, $graph_dissassembly, "Should find the output graph somewhere");
423 check_graph_vs_output ($chart, $got);
429 my $chart = cmpthese( 10, $code_to_test, 'nop' ) ;
431 ok ($foo > 0, "Foo code was run");
432 ok ($bar > 0, "Bar code was run");
435 # Remove any warnings about having too few iterations.
436 $got =~ s/\(warning:[^\)]+\)//gs;
437 like ($got, qr/timing 10 iterations of\s+Bar\W+Foo\W*?\.\.\./s,
440 $got =~ s/.*\.\.\.//s;
441 like ($got, $Nop_Pattern, 'specify format as nop');
442 like ($got, $graph_dissassembly, "Should find the output graph somewhere");
443 check_graph_vs_output ($chart, $got);
449 my $chart = cmpthese( 10, $code_to_test, 'none' ) ;
451 ok ($foo > 0, "Foo code was run");
452 ok ($bar > 0, "Bar code was run");
455 # Remove any warnings about having too few iterations.
456 $got =~ s/\(warning:[^\)]+\)//gs;
457 $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning
458 is ($got, '', "format 'none' should suppress output");
459 is (ref $chart, 'ARRAY', "output should be an array ref");
460 # Some of these will go bang if the preceding test fails. There will be
461 # a big clue as to why, from the previous test's diagnostic
462 is (ref $chart->[0], 'ARRAY', "output should be an array of arrays");
463 check_graph (@$chart);
469 my $chart = cmpthese( $results ) ;
471 is ($foo, 0, "Foo code was not run");
472 is ($bar, 0, "Bar code was not run");
475 ok ($got !~ /\.\.\./s, 'check that there is no title');
476 like ($got, $graph_dissassembly, "Should find the output graph somewhere");
477 check_graph_vs_output ($chart, $got);
483 my $chart = cmpthese( $results, 'none' ) ;
485 is ($foo, 0, "Foo code was not run");
486 is ($bar, 0, "Bar code was not run");
489 is ($got, '', "'none' should suppress all output");
490 is (ref $chart, 'ARRAY', "output should be an array ref");
491 # Some of these will go bang if the preceding test fails. There will be
492 # a big clue as to why, from the previous test's diagnostic
493 is (ref $chart->[0], 'ARRAY', "output should be an array of arrays");
494 check_graph (@$chart);
497 ###}my $out = tie *OUT, 'TieOut'; my ($got); ###
499 my $debug = tie *STDERR, 'TieOut';
502 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
503 is ($bar, 5, "benchmarked code was run 5 times");
504 is ($debug->read(), '', "There was no debug output");
510 $got = timeit(5, '++$bar');
512 isa_ok($got, 'Benchmark', "timeit eval");
513 is ($bar, 5, "benchmarked code was run 5 times");
514 is ($out->read(), '', "There was no STDOUT output with debug enabled");
515 isnt ($debug->read(), '', "There was STDERR debug output with debug enabled");
520 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
521 is ($bar, 5, "benchmarked code was run 5 times");
522 is ($debug->read(), '', "There was no debug output debug disabled");
527 # To check the cache we are poking where we don't belong, inside the namespace.
528 # The way benchmark is written We can't actually check whehter the cache is
529 # being used, merely what's become cached.
532 my @before_keys = keys %Benchmark::Cache;
534 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
535 is ($bar, 5, "benchmarked code was run 5 times");
536 my @after5_keys = keys %Benchmark::Cache;
538 isa_ok(timeit(10, '++$bar'), 'Benchmark', "timeit eval");
539 is ($bar, 10, "benchmarked code was run 10 times");
540 ok (!eq_array ([keys %Benchmark::Cache], \@after5_keys), "10 differs from 5");
543 # Hash key order will be the same if there are the same keys.
544 is_deeply ([keys %Benchmark::Cache], \@after5_keys,
545 "cleared 10, only cached results for 5 should remain");
548 is_deeply ([keys %Benchmark::Cache], \@before_keys,
549 "back to square 1 when we clear the cache again?");
552 { # Check usage error messages
553 my %usage = %Benchmark::_Usage;
554 delete $usage{runloop}; # not public, not worrying about it just now
556 my @takes_no_args = qw(clearallcache disablecache enablecache);
558 my %cmpthese = ('forgot {}' => 'cmpthese( 42, foo => sub { 1 } )',
559 'not result' => 'cmpthese(42)',
560 'array ref' => 'cmpthese( 42, [ foo => sub { 1 } ] )',
562 while( my($name, $code) = each %cmpthese ) {
564 is( $@, $usage{cmpthese}, "cmpthese usage: $name" );
567 my %timethese = ('forgot {}' => 'timethese( 42, foo => sub { 1 } )',
568 'no code' => 'timethese(42)',
569 'array ref' => 'timethese( 42, [ foo => sub { 1 } ] )',
572 while( my($name, $code) = each %timethese ) {
574 is( $@, $usage{timethese}, "timethese usage: $name" );
578 while( my($func, $usage) = each %usage ) {
579 next if grep $func eq $_, @takes_no_args;
581 is( $@, $usage, "$func usage: no args" );
584 foreach my $func (@takes_no_args) {
586 like( $@, qr/Too many arguments for Benchmark::$func/, "$func usage: with args" );
595 bless(\( my $ref = ''), $class);
600 $$self .= join('', @_);
605 $$self .= sprintf shift, @_;
610 return substr($$self, 0, length($$self), '');