#!./perl -w BEGIN { chdir 't' if -d 't'; @INC = ('../lib'); } use warnings; use strict; our ($foo, $bar, $baz, $ballast); use Test::More tests => 213; use Benchmark qw(:all); my $DELTA = 0.4; # Some timing ballast sub fib { my $n = shift; return $n if $n < 2; fib($n-1) + fib($n-2); } $ballast = 15; my $All_Pattern = qr/(\d+) +wallclock secs? +\( *(-?\d+\.\d\d) +usr +(-?\d+\.\d\d) +sys +\+ +(-?\d+\.\d\d) +cusr +(-?\d+\.\d\d) +csys += +(-?\d+\.\d\d) +CPU\)/; my $Noc_Pattern = qr/(\d+) +wallclock secs? +\( *(-?\d+\.\d\d) +usr +\+ +(-?\d+\.\d\d) +sys += +(-?\d+\.\d\d) +CPU\)/; my $Nop_Pattern = qr/(\d+) +wallclock secs? +\( *(-?\d+\.\d\d) +cusr +\+ +(-?\d+\.\d\d) +csys += +\d+\.\d\d +CPU\)/; # Please don't trust the matching parentheses to be useful in this :-) my $Default_Pattern = qr/$All_Pattern|$Noc_Pattern/; # see if the ratio of two integer values is within (1+$delta) sub cmp_delta { my ($min, $max, $delta) = @_; ($min, $max) = ($max, $min) if $max < $min; return 0 if $min < 1; # avoid / 0 return $max/$min <= (1+$delta); } my $t0 = new Benchmark; isa_ok ($t0, 'Benchmark', "Ensure we can create a benchmark object"); # We use the benchmark object once we've done some work: isa_ok(timeit(5, sub {++$foo}), 'Benchmark', "timeit CODEREF"); is ($foo, 5, "benchmarked code was run 5 times"); isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval"); is ($bar, 5, "benchmarked code was run 5 times"); # is coderef called with spurious arguments? timeit( 1, sub { $foo = @_ }); is ($foo, 0, "benchmarked code called without arguments"); print "# Burning CPU to benchmark things; will take time...\n"; # We need to do something fairly slow in the coderef. # Same coderef. Same place in memory. my $coderef = sub {$baz += fib($ballast)}; # The default is three. $baz = 0; my $threesecs = countit(0, $coderef); isa_ok($threesecs, 'Benchmark', "countit 0, CODEREF"); isnt ($baz, 0, "benchmarked code was run"); my $in_threesecs = $threesecs->iters; print "# in_threesecs=$in_threesecs iterations\n"; cmp_ok($in_threesecs, '>', 0, "iters returned positive iterations"); my $cpu3 = $threesecs->[1]; # user my $sys3 = $threesecs->[2]; # sys cmp_ok($cpu3+$sys3, '>=', 3.0, "3s cpu3 is at least 3s"); my $in_threesecs_adj = $in_threesecs; $in_threesecs_adj *= (3/$cpu3); # adjust because may not have run for exactly 3s print "# in_threesecs_adj=$in_threesecs_adj adjusted iterations\n"; my $estimate = int (100 * $in_threesecs_adj / 3) / 100; print "# from the 3 second run estimate $estimate iterations in 1 second...\n"; $baz = 0; my $onesec = countit(1, $coderef); isa_ok($onesec, 'Benchmark', "countit 1, CODEREF"); isnt ($baz, 0, "benchmarked code was run"); my $in_onesec = $onesec->iters; print "# in_onesec=$in_onesec iterations\n"; cmp_ok($in_onesec, '>', 0, "iters returned positive iterations"); my $cpu1 = $onesec->[1]; # user my $sys1 = $onesec->[2]; # sys cmp_ok($cpu1+$sys1, '>=', 1.0, "is cpu1 is at least 1s"); my $in_onesec_adj = $in_onesec; $in_onesec_adj *= (1/$cpu1); # adjust because may not have run for exactly 1s print "# in_onesec_adj=$in_onesec_adj adjusted iterations\n"; # I found that the eval'ed version was 3 times faster than the coderef. # (now it has a different ballast value) $baz = 0; my $again = countit(1, '$baz += fib($ballast)'); isa_ok($onesec, 'Benchmark', "countit 1, eval"); isnt ($baz, 0, "benchmarked code was run"); my $in_again = $again->iters; print "# $in_again iterations\n"; cmp_ok($in_again, '>', 0, "iters returned positive iterations"); my $t1 = new Benchmark; isa_ok ($t1, 'Benchmark', "Create another benchmark object now we're finished"); my $diff = timediff ($t1, $t0); isa_ok ($diff, 'Benchmark', "Get the time difference"); isa_ok (timesum ($t0, $t1), 'Benchmark', "check timesum"); my $default = timestr ($diff); isnt ($default, '', 'timestr ($diff)'); my $auto = timestr ($diff, 'auto'); is ($auto, $default, 'timestr ($diff, "auto") matches timestr ($diff)'); { my $all = timestr ($diff, 'all'); like ($all, $All_Pattern, 'timestr ($diff, "all")'); print "# $all\n"; my ($wallclock, $usr, $sys, $cusr, $csys, $cpu) = $all =~ $All_Pattern; is (timestr ($diff, 'none'), '', "none suppresses output"); my $noc = timestr ($diff, 'noc'); like ($noc, qr/$wallclock +wallclock secs? +\( *$usr +usr +\+ +$sys +sys += +\d+\.\d\d +CPU\)/, 'timestr ($diff, "noc")'); my $nop = timestr ($diff, 'nop'); like ($nop, qr/$wallclock +wallclock secs? +\( *$cusr +cusr +\+ +$csys +csys += +\d+\.\d\d +CPU\)/, 'timestr ($diff, "nop")'); if ($auto eq $noc) { pass ('"auto" is "noc"'); } else { is ($auto, $all, '"auto" isn\'t "noc", so should be eq to "all"'); } like (timestr ($diff, 'all', 'E'), 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"]'); } my $out = tie *OUT, 'TieOut'; my $iterations = 100; $foo = 0; select(OUT); my $got = timethis($iterations, sub {++$foo}); select(STDOUT); isa_ok($got, 'Benchmark', "timethis CODEREF"); is ($foo, $iterations, "benchmarked code was run $iterations times"); $got = $out->read(); like ($got, qr/^timethis $iterations/, 'default title'); like ($got, $Default_Pattern, 'default format is all or noc'); $bar = 0; select(OUT); $got = timethis($iterations, '++$bar'); select(STDOUT); isa_ok($got, 'Benchmark', "timethis eval"); is ($bar, $iterations, "benchmarked code was run $iterations times"); $got = $out->read(); like ($got, qr/^timethis $iterations/, 'default title'); like ($got, $Default_Pattern, 'default format is all or noc'); my $title = 'lies, damn lies and benchmarks'; $foo = 0; select(OUT); $got = timethis($iterations, sub {++$foo}, $title); select(STDOUT); isa_ok($got, 'Benchmark', "timethis with title"); is ($foo, $iterations, "benchmarked code was run $iterations times"); $got = $out->read(); like ($got, qr/^$title:/, 'specify title'); like ($got, $Default_Pattern, 'default format is all or noc'); # default is auto, which is all or noc. nop can never match the default $foo = 0; select(OUT); $got = timethis($iterations, sub {++$foo}, $title, 'nop'); select(STDOUT); isa_ok($got, 'Benchmark', "timethis with format"); is ($foo, $iterations, "benchmarked code was run $iterations times"); $got = $out->read(); like ($got, qr/^$title:/, 'specify title'); like ($got, $Nop_Pattern, 'specify format as nop'); { $foo = 0; select(OUT); my $start = time; $got = timethis(-2, sub {$foo+= fib($ballast)}, $title, 'none'); my $end = time; select(STDOUT); isa_ok($got, 'Benchmark', "timethis, at least 2 seconds with format 'none'"); cmp_ok($foo, '>', 0, "benchmarked code was run"); cmp_ok($end - $start, '>', 1, "benchmarked code ran for over 1 second"); $got = $out->read(); # Remove any warnings about having too few iterations. $got =~ s/\(warning:[^\)]+\)//gs; $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning is ($got, '', "format 'none' should suppress output"); } $foo = $bar = $baz = 0; select(OUT); $got = timethese($iterations, { Foo => sub {++$foo}, Bar => '++$bar', Baz => sub {++$baz} }); select(STDOUT); is(ref ($got), 'HASH', "timethese should return a hashref"); isa_ok($got->{Foo}, 'Benchmark', "Foo value"); isa_ok($got->{Bar}, 'Benchmark', "Bar value"); isa_ok($got->{Baz}, 'Benchmark', "Baz value"); eq_set([keys %$got], [qw(Foo Bar Baz)], 'should be exactly three objects'); is ($foo, $iterations, "Foo code was run $iterations times"); is ($bar, $iterations, "Bar code was run $iterations times"); is ($baz, $iterations, "Baz code was run $iterations times"); $got = $out->read(); # Remove any warnings about having too few iterations. $got =~ s/\(warning:[^\)]+\)//gs; like ($got, qr/timing $iterations iterations of\s+Bar\W+Baz\W+Foo\W*?\.\.\./s, 'check title'); # Remove the title $got =~ s/.*\.\.\.//s; like ($got, qr/\bBar\b.*\bBaz\b.*\bFoo\b/s, 'check output is in sorted order'); like ($got, $Default_Pattern, 'should find default format somewhere'); { # ensure 'use strict' does not leak from Benchmark.pm into benchmarked code no strict; select OUT; eval { timethese( 1, { undeclared_var => q{ $i++; $i-- }, symbolic_ref => q{ $bar = 42; $foo = 'bar'; $q = ${$foo} }, }, 'none' ); }; is( $@, '', q{no strict leakage in name => 'code'} ); eval { timethese( 1, { undeclared_var => sub { $i++; $i-- }, symbolic_ref => sub { $bar = 42; $foo = 'bar'; return ${$foo} }, }, 'none' ); }; is( $@, '', q{no strict leakage in name => sub { code }} ); # clear out buffer $out->read; } my $code_to_test = { Foo => sub {$foo+=fib($ballast-2)}, Bar => sub {$bar+=fib($ballast)}}; # Keep these for later. my $results; { $foo = $bar = 0; select(OUT); my $start = times; $results = timethese(-0.1, $code_to_test, 'none'); my $end = times; select(STDOUT); is(ref ($results), 'HASH', "timethese should return a hashref"); isa_ok($results->{Foo}, 'Benchmark', "Foo value"); isa_ok($results->{Bar}, 'Benchmark', "Bar value"); eq_set([keys %$results], [qw(Foo Bar)], 'should be exactly two objects'); cmp_ok($foo, '>', 0, "Foo code was run"); cmp_ok($bar, '>', 0, "Bar code was run"); cmp_ok($end-$start, '>', 0.1, "benchmarked code ran for over 0.1 seconds"); $got = $out->read(); # Remove any warnings about having too few iterations. $got =~ s/\(warning:[^\)]+\)//gs; is ($got =~ tr/ \t\n//c, 0, "format 'none' should suppress output"); } my $graph_dissassembly = qr!^[ \t]+(\S+)[ \t]+(\w+)[ \t]+(\w+)[ \t]* # Title line \n[ \t]*(\w+)[ \t]+([0-9.]+(?:/s)?)[ \t]+(-+)[ \t]+(-?\d+%)[ \t]* \n[ \t]*(\w+)[ \t]+([0-9.]+(?:/s)?)[ \t]+(-?\d+%)[ \t]+(-+)[ \t]*$!xm; sub check_graph_consistency { my ( $ratetext, $slowc, $fastc, $slowr, $slowratet, $slowslow, $slowfastt, $fastr, $fastratet, $fastslowt, $fastfast) = @_; note("calling check_graph_consistency from line " . (caller(1))[2]); my $all_passed = 1; $all_passed &= is ($slowc, $slowr, "left col tag should be top row tag"); $all_passed &= is ($fastc, $fastr, "right col tag should be bottom row tag"); $all_passed &= like ($slowslow, qr/^-+/, "should be dash for comparing slow with slow"); $all_passed &= is ($slowslow, $fastfast, "slow v slow should be same as fast v fast"); my $slowrate = $slowratet; my $fastrate = $fastratet; my ($slow_is_rate, $fast_is_rate); unless ($slow_is_rate = $slowrate =~ s!/s!!) { # Slow is expressed as iters per second. $slowrate = 1/$slowrate if $slowrate; } unless ($fast_is_rate = $fastrate =~ s!/s!!) { # Fast is expressed as iters per second. $fastrate = 1/$fastrate if $fastrate; } if ($ratetext =~ /rate/i) { $all_passed &= ok ($slow_is_rate, "slow should be expressed as a rate"); $all_passed &= ok ($fast_is_rate, "fast should be expressed as a rate"); } else { $all_passed &= ok (!$slow_is_rate, "slow should be expressed as a iters per second"); $all_passed &= ok (!$fast_is_rate, "fast should be expressed as a iters per second"); } (my $slowfast = $slowfastt) =~ s!%!!; (my $fastslow = $fastslowt) =~ s!%!!; if ($slowrate < $fastrate) { pass ("slow rate is less than fast rate"); unless (ok ($slowfast <= 0 && $slowfast >= -100, "slowfast should be less than or equal to zero, and >= -100")) { diag("slowfast=$slowfast"); $all_passed = 0; } unless (cmp_ok($fastslow, '>', 0, "fastslow should be > 0")) { $all_passed = 0; } } else { $all_passed &= is ($slowrate, $fastrate, "slow rate isn't less than fast rate, so should be the same"); # In OpenBSD the $slowfast is sometimes a really, really, really # small number less than zero, and this gets stringified as -0. $all_passed &= like ($slowfast, qr/^-?0$/, "slowfast should be zero"); $all_passed &= like ($fastslow, qr/^-?0$/, "fastslow should be zero"); } return $all_passed; } sub check_graph_vs_output { my ($chart, $got) = @_; my ( $ratetext, $slowc, $fastc, $slowr, $slowratet, $slowslow, $slowfastt, $fastr, $fastratet, $fastslowt, $fastfast) = $got =~ $graph_dissassembly; my $all_passed = check_graph_consistency ( $ratetext, $slowc, $fastc, $slowr, $slowratet, $slowslow, $slowfastt, $fastr, $fastratet, $fastslowt, $fastfast); $all_passed &= is_deeply ($chart, [['', $ratetext, $slowc, $fastc], [$slowr, $slowratet, $slowslow, $slowfastt], [$fastr, $fastratet, $fastslowt, $fastfast]], "check the chart layout matches the formatted output"); unless ($all_passed) { diag("Something went wrong there. I got this chart:\n$got"); } } sub check_graph { my ($title, $row1, $row2) = @_; is (scalar @$title, 4, "Four entries in title row"); is (scalar @$row1, 4, "Four entries in first row"); is (scalar @$row2, 4, "Four entries in second row"); is (shift @$title, '', "First entry of output graph should be ''"); check_graph_consistency (@$title, @$row1, @$row2); } { select(OUT); my $start = times; my $chart = cmpthese( -0.1, { a => "\$i = sqrt(\$i++) * sqrt(\$i) for 1..10", b => "\$i = sqrt(\$i++)", }, "auto" ) ; my $end = times; select(STDOUT); cmp_ok($end - $start, '>', 0.05, "benchmarked code ran for over 0.05 seconds"); $got = $out->read(); # Remove any warnings about having too few iterations. $got =~ s/\(warning:[^\)]+\)//gs; like ($got, qr/running\W+a\W+b.*?for at least 0\.1 CPU second/s, 'check title'); # Remove the title $got =~ s/.*\.\.\.//s; like ($got, $Default_Pattern, 'should find default format somewhere'); like ($got, $graph_dissassembly, "Should find the output graph somewhere"); check_graph_vs_output ($chart, $got); } # Not giving auto should suppress timethese results. { select(OUT); my $start = times; my $chart = cmpthese( -0.1, { a => "\$i = sqrt(\$i++) * sqrt(\$i) for 1..10", b => "\$i = sqrt(\$i++)" }); my $end = times; select(STDOUT); cmp_ok($end - $start, '>', 0.05, "benchmarked code ran for over 0.05 seconds"); $got = $out->read(); # Remove any warnings about having too few iterations. $got =~ s/\(warning:[^\)]+\)//gs; unlike ($got, qr/running\W+a\W+b.*?for at least 0\.1 CPU second/s, 'should not have title'); # Remove the title $got =~ s/.*\.\.\.//s; unlike ($got, $Default_Pattern, 'should not find default format somewhere'); like ($got, $graph_dissassembly, "Should find the output graph somewhere"); check_graph_vs_output ($chart, $got); } { $foo = $bar = 0; select(OUT); my $chart = cmpthese($iterations, $code_to_test, 'nop' ) ; select(STDOUT); cmp_ok($foo, '>', 0, "Foo code was run"); cmp_ok($bar, '>', 0, "Bar code was run"); $got = $out->read(); # Remove any warnings about having too few iterations. $got =~ s/\(warning:[^\)]+\)//gs; like ($got, qr/timing $iterations iterations of\s+Bar\W+Foo\W*?\.\.\./s, 'check title'); # Remove the title $got =~ s/.*\.\.\.//s; like ($got, $Nop_Pattern, 'specify format as nop'); like ($got, $graph_dissassembly, "Should find the output graph somewhere"); check_graph_vs_output ($chart, $got); } { $foo = $bar = 0; select(OUT); my $chart = cmpthese($iterations, $code_to_test, 'none' ) ; select(STDOUT); cmp_ok($foo, '>', 0, "Foo code was run"); cmp_ok($bar, '>', 0, "Bar code was run"); $got = $out->read(); # Remove any warnings about having too few iterations. $got =~ s/\(warning:[^\)]+\)//gs; $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning is ($got, '', "format 'none' should suppress output"); is (ref $chart, 'ARRAY', "output should be an array ref"); # Some of these will go bang if the preceding test fails. There will be # a big clue as to why, from the previous test's diagnostic is (ref $chart->[0], 'ARRAY', "output should be an array of arrays"); check_graph (@$chart); } # this is a repeat of the above test, but with the timing and charting # steps split. { $foo = $bar = 0; select(OUT); my $res = timethese($iterations, $code_to_test, 'none' ) ; my $chart = cmpthese($res, 'none' ) ; select(STDOUT); cmp_ok($foo, '>', 0, "Foo code was run"); cmp_ok($bar, '>', 0, "Bar code was run"); $got = $out->read(); # Remove any warnings about having too few iterations. $got =~ s/\(warning:[^\)]+\)//gs; $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning is ($got, '', "format 'none' should suppress output"); is (ref $chart, 'ARRAY', "output should be an array ref"); # Some of these will go bang if the preceding test fails. There will be # a big clue as to why, from the previous test's diagnostic is (ref $chart->[0], 'ARRAY', "output should be an array of arrays"); use Data::Dumper; check_graph(@$chart) or diag(Data::Dumper->Dump([$res, $chart], ['$res', '$chart'])); } { $foo = $bar = 0; select(OUT); my $chart = cmpthese( $results ) ; select(STDOUT); is ($foo, 0, "Foo code was not run"); is ($bar, 0, "Bar code was not run"); $got = $out->read(); unlike($got, qr/\.\.\./s, 'check that there is no title'); like ($got, $graph_dissassembly, "Should find the output graph somewhere"); check_graph_vs_output ($chart, $got); } { $foo = $bar = 0; select(OUT); my $chart = cmpthese( $results, 'none' ) ; select(STDOUT); is ($foo, 0, "Foo code was not run"); is ($bar, 0, "Bar code was not run"); $got = $out->read(); is ($got, '', "'none' should suppress all output"); is (ref $chart, 'ARRAY', "output should be an array ref"); # Some of these will go bang if the preceding test fails. There will be # a big clue as to why, from the previous test's diagnostic is (ref $chart->[0], 'ARRAY', "output should be an array of arrays"); check_graph (@$chart); } ###}my $out = tie *OUT, 'TieOut'; my ($got); ### my $debug = tie *STDERR, 'TieOut'; $bar = 0; isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval"); is ($bar, 5, "benchmarked code was run 5 times"); is ($debug->read(), '', "There was no debug output"); Benchmark->debug(1); $bar = 0; select(OUT); $got = timeit(5, '++$bar'); select(STDOUT); isa_ok($got, 'Benchmark', "timeit eval"); is ($bar, 5, "benchmarked code was run 5 times"); is ($out->read(), '', "There was no STDOUT output with debug enabled"); isnt ($debug->read(), '', "There was STDERR debug output with debug enabled"); Benchmark->debug(0); $bar = 0; isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval"); is ($bar, 5, "benchmarked code was run 5 times"); is ($debug->read(), '', "There was no debug output debug disabled"); undef $debug; untie *STDERR; # To check the cache we are poking where we don't belong, inside the namespace. # The way benchmark is written we can't actually check whether the cache is # being used, merely what's become cached. clearallcache(); my @before_keys = keys %Benchmark::Cache; $bar = 0; isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval"); is ($bar, 5, "benchmarked code was run 5 times"); my @after5_keys = keys %Benchmark::Cache; $bar = 0; isa_ok(timeit(10, '++$bar'), 'Benchmark', "timeit eval"); is ($bar, 10, "benchmarked code was run 10 times"); ok (!eq_array ([keys %Benchmark::Cache], \@after5_keys), "10 differs from 5"); clearcache(10); # Hash key order will be the same if there are the same keys. is_deeply ([keys %Benchmark::Cache], \@after5_keys, "cleared 10, only cached results for 5 should remain"); clearallcache(); is_deeply ([keys %Benchmark::Cache], \@before_keys, "back to square 1 when we clear the cache again?"); { # Check usage error messages my %usage = %Benchmark::_Usage; delete $usage{runloop}; # not public, not worrying about it just now my @takes_no_args = qw(clearallcache disablecache enablecache); my %cmpthese = ('forgot {}' => 'cmpthese( 42, foo => sub { 1 } )', 'not result' => 'cmpthese(42)', 'array ref' => 'cmpthese( 42, [ foo => sub { 1 } ] )', ); while( my($name, $code) = each %cmpthese ) { eval $code; is( $@, $usage{cmpthese}, "cmpthese usage: $name" ); } my %timethese = ('forgot {}' => 'timethese( 42, foo => sub { 1 } )', 'no code' => 'timethese(42)', 'array ref' => 'timethese( 42, [ foo => sub { 1 } ] )', ); while( my($name, $code) = each %timethese ) { eval $code; is( $@, $usage{timethese}, "timethese usage: $name" ); } while( my($func, $usage) = each %usage ) { next if grep $func eq $_, @takes_no_args; eval "$func()"; is( $@, $usage, "$func usage: no args" ); } foreach my $func (@takes_no_args) { eval "$func(42)"; is( $@, $usage{$func}, "$func usage: with args" ); } } package TieOut; sub TIEHANDLE { my $class = shift; bless(\( my $ref = ''), $class); } sub PRINT { my $self = shift; $$self .= join('', @_); } sub PRINTF { my $self = shift; $$self .= sprintf shift, @_; } sub read { my $self = shift; return substr($$self, 0, length($$self), ''); }