Benchmark test from Nicholas Clark.

p4raw-id: //depot/perl@13693

2 files changed, 494 insertions, 3 deletions

diff --git a/lib/Benchmark.pm b/lib/Benchmark.pm
index 3f8eb62d07..175c9c63ec 100644
--- a/lib/Benchmark.pm
+++ b/lib/Benchmark.pm
@@ -389,6 +389,12 @@ September, 1999; by Barrie Slaymaker: math fixes and accuracy and
 efficiency tweaks.  Added cmpthese().  A result is now returned from 
 timethese().  Exposed countit() (was runfor()).
 
+December, 2001; by Nicholas Clark: make timestr() recognise the style 'none'
+and return an empty string. If cmpthese is calling timethese, make it pass the
+style in. (so that 'none' will suppress output). Make sub new dump its
+debugging output to STDERR, to be consistent with everything else.
+All bugs found while writing a regression test.
+
 =cut
 
 # evaluate something in a clean lexical environment
@@ -406,7 +412,7 @@ use Exporter;
 	      clearcache clearallcache disablecache enablecache);
 %EXPORT_TAGS=( all => [ @EXPORT, @EXPORT_OK ] ) ;
 
-$VERSION = 1.03;
+$VERSION = 1.04;
 
 &init;
 
@@ -435,7 +441,7 @@ sub disablecache  { $cache = 0; }
 # --- Functions to process the 'time' data type
 
 sub new { my @t = (time, times, @_ == 2 ? $_[1] : 0);
-	  print "new=@t\n" if $debug;
+	  print STDERR "new=@t\n" if $debug;
 	  bless \@t; }
 
 sub cpu_p { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $pu+$ps         ; }
@@ -471,6 +477,7 @@ sub timestr {
     $f = $defaultfmt unless defined $f;
     # format a time in the required style, other formats may be added here
     $style ||= $defaultstyle;
+    return '' if $style eq 'none';
     $style = ($ct>0) ? 'all' : 'noc' if $style eq 'auto';
     my $s = "@t $style"; # default for unknown style
     $s=sprintf("%2d wallclock secs (%$f usr %$f sys + %$f cusr %$f csys = %$f CPU)",
@@ -706,7 +713,7 @@ sub timethese{
 }
 
 sub cmpthese{
-    my ($results, $style) = ref $_[0] ? @_ : ( timethese( @_[0,1] ), $_[2] ) ;
+    my ($results, $style) = ref $_[0] ? @_ : ( timethese( @_[0,1,2] ), $_[2] ) ;
 
     $style = "" unless defined $style;
 
diff --git a/lib/Benchmark.t b/lib/Benchmark.t
new file mode 100644
index 0000000000..2b5e1b4fb3
--- /dev/null
+++ b/lib/Benchmark.t
@@ -0,0 +1,484 @@
+#!./perl -w
+
+BEGIN {
+    chdir 't' if -d 't';
+    @INC = '../lib';
+}
+
+use warnings;
+use strict;
+use vars qw($foo $bar $baz $ballast);
+use Test::More tests => 159;
+
+use Benchmark qw(:all);
+
+my $delta = 0.2;
+
+# 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 parenthises to be useful in this :-)
+my $default_pattern = qr/$all_pattern|$noc_pattern/;
+
+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");
+
+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 iterations\n";
+ok ($in_threesecs > 0, "iters returned positive iterations");
+
+my $estimate = int ($in_threesecs / 3);
+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 iterations\n";
+ok ($in_onesec > 0, "iters returned positive iterations");
+
+my $difference = $in_onesec - $estimate;
+ok (abs ($difference / $in_onesec) < $delta,
+    "is $in_onesec within $delta of estimate ($estimate)");
+
+# 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";
+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 supresses output");
+
+    my $noc = timestr ($diff, 'noc');
+    like ($noc, qr/$wallclock +wallclock secs? +\( *$usr +usr +\+ +$sys +sys += +$cpu +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 = 3;
+
+$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'");
+    ok ($foo > 0, "benchmarked code was run");
+    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');
+
+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');
+    ok ($foo > 0, "Foo code was run");
+    ok ($bar > 0, "Bar code was run");
+
+    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)
+        = @_;
+    is ($slowc, $slowr, "left col tag should be top row tag");
+    is ($fastc, $fastr, "right col tag should be bottom row tag");
+    like ($slowslow, qr/^-+/, "should be dash for comparing slow with slow");
+    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) {
+        ok ($slow_is_rate, "slow should be expressed as a rate");
+        ok ($fast_is_rate, "fast should be expressed as a rate");
+    } else {
+        ok (!$slow_is_rate, "slow should be expressed as a iters per second");
+        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");
+        ok ($slowfast < 0 && $slowfast > -100,
+            "slowfast should be less than zero, and > -100");
+        ok ($fastslow > 100, "fastslow should be > 100");
+    } else {
+        is ($slowrate, $fastrate,
+            "slow rate isn't less than fast rate, so should be the same");
+        is ($slowfast, 0, "slowfast should be zero");
+        is ($fastslow, 0, "fastslow should be zero");
+    }
+}
+
+sub check_graph_vs_output {
+    my ($chart, $got) = @_;
+    my (	$ratetext, $slowc, $fastc,
+        $slowr, $slowratet, $slowslow, $slowfastt,
+        $fastr, $fastratet, $fastslowt, $fastfast)
+        = $got =~ $graph_dissassembly;
+    check_graph_consistency (        $ratetext, $slowc, $fastc,
+                             $slowr, $slowratet, $slowslow, $slowfastt,
+                             $fastr, $fastratet, $fastslowt, $fastfast);
+    is_deeply ($chart, [['', $ratetext, $slowc, $fastc],
+                        [$slowr, $slowratet, $slowslow, $slowfastt],
+                        [$fastr, $fastratet, $fastslowt, $fastfast]],
+               "check the chart layout matches the formatted output");
+}
+
+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", b => "\$i *= 2" } ) ;
+    my $end = times;
+    select(STDOUT);
+    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);
+}
+
+{
+    $foo = $bar = 0;
+    select(OUT);
+    my $chart = cmpthese( 10, $code_to_test, 'nop' ) ;
+    select(STDOUT);
+    ok ($foo > 0, "Foo code was run");
+    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 10 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( 10, $code_to_test, 'none' ) ;
+    select(STDOUT);
+    ok ($foo > 0, "Foo code was run");
+    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);
+}
+
+{
+    $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();
+    ok ($got !~ /\.\.\./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 whehter 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?");
+
+
+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), '');
+}