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     my $all_passed = 1;
 256     $all_passed
 257       &= is ($slowc, $slowr, "left col tag should be top row tag");
 258     $all_passed
 259       &= is ($fastc, $fastr, "right col tag should be bottom row tag");
 260     $all_passed &=
 261       like ($slowslow, qr/^-+/, "should be dash for comparing slow with slow");
 262     $all_passed
 263       &= is ($slowslow, $fastfast, "slow v slow should be same as fast v fast");
 264     my $slowrate = $slowratet;
 265     my $fastrate = $fastratet;
 266     my ($slow_is_rate, $fast_is_rate);
 267     unless ($slow_is_rate = $slowrate =~ s!/s!!) {
 268         # Slow is expressed as iters per second.
 269         $slowrate = 1/$slowrate if $slowrate;
 270     }
 271     unless ($fast_is_rate = $fastrate =~ s!/s!!) {
 272         # Fast is expressed as iters per second.
 273         $fastrate = 1/$fastrate if $fastrate;
 274     }
 275     if ($ratetext =~ /rate/i) {
 276         $all_passed
 277           &= ok ($slow_is_rate, "slow should be expressed as a rate");
 278         $all_passed
 279           &= ok ($fast_is_rate, "fast should be expressed as a rate");
 280     } else {
 281         $all_passed &=
 282           ok (!$slow_is_rate, "slow should be expressed as a iters per second");
 283         $all_passed &=
 284           ok (!$fast_is_rate, "fast should be expressed as a iters per second");
 285     }
 286
 287     (my $slowfast = $slowfastt) =~ s!%!!;
 288     (my $fastslow = $fastslowt) =~ s!%!!;
 289     if ($slowrate < $fastrate) {
 290         pass ("slow rate is less than fast rate");
 291         unless (ok ($slowfast < 0 && $slowfast >= -100,
 292                     "slowfast should be less than zero, and >= -100")) {
 293           print STDERR "# slowfast $slowfast\n";
 294           $all_passed = 0;
 295         }
 296         unless (ok ($fastslow > 0, "fastslow should be > 0")) {
 297           print STDERR "# fastslow $fastslow\n";
 298           $all_passed = 0;
 299         }
 300     } else {
 301         $all_passed
 302           &= is ($slowrate, $fastrate,
 303                  "slow rate isn't less than fast rate, so should be the same");
 304         $all_passed
 305           &= is ($slowfast, 0, "slowfast should be zero");
 306         $all_passed
 307           &= is ($fastslow, 0, "fastslow should be zero");
 308     }
 309     return $all_passed;
 310 }
 311
 312 sub check_graph_vs_output {
 313     my ($chart, $got) = @_;
 314     my (        $ratetext, $slowc, $fastc,
 315         $slowr, $slowratet, $slowslow, $slowfastt,
 316         $fastr, $fastratet, $fastslowt, $fastfast)
 317         = $got =~ $graph_dissassembly;
 318     my $all_passed
 319       = check_graph_consistency (        $ratetext, $slowc, $fastc,
 320                                  $slowr, $slowratet, $slowslow, $slowfastt,
 321                                  $fastr, $fastratet, $fastslowt, $fastfast);
 322     $all_passed
 323       &= is_deeply ($chart, [['', $ratetext, $slowc, $fastc],
 324                              [$slowr, $slowratet, $slowslow, $slowfastt],
 325                              [$fastr, $fastratet, $fastslowt, $fastfast]],
 326                     "check the chart layout matches the formatted output");
 327     unless ($all_passed) {
 328       print STDERR "# Something went wrong there. I got this chart:\n";
 329       print STDERR "# $_\n" foreach split /\n/, $got;
 330     }
 331 }
 332
 333 sub check_graph {
 334     my ($title, $row1, $row2) = @_;
 335     is (scalar @$title, 4, "Four entries in title row");
 336     is (scalar @$row1, 4, "Four entries in first row");
 337     is (scalar @$row2, 4, "Four entries in second row");
 338     is (shift @$title, '', "First entry of output graph should be ''");
 339     check_graph_consistency (@$title, @$row1, @$row2);
 340 }
 341
 342 {
 343     select(OUT);
 344     my $start = times;
 345     my $chart = cmpthese( -0.1, { a => "++\$i", b => "\$i = sqrt(\$i++)" } ) ;
 346     my $end = times;
 347     select(STDOUT);
 348     ok (($end - $start) > 0.05, "benchmarked code ran for over 0.05 seconds");
 349
 350     $got = $out->read();
 351     # Remove any warnings about having too few iterations.
 352     $got =~ s/\(warning:[^\)]+\)//gs;
 353
 354     like ($got, qr/running\W+a\W+b.*?for at least 0\.1 CPU second/s,
 355           'check title');
 356     # Remove the title
 357     $got =~ s/.*\.\.\.//s;
 358     like ($got, $default_pattern, 'should find default format somewhere');
 359     like ($got, $graph_dissassembly, "Should find the output graph somewhere");
 360     check_graph_vs_output ($chart, $got);
 361 }
 362
 363 {
 364     $foo = $bar = 0;
 365     select(OUT);
 366     my $chart = cmpthese( 10, $code_to_test, 'nop' ) ;
 367     select(STDOUT);
 368     ok ($foo > 0, "Foo code was run");
 369     ok ($bar > 0, "Bar code was run");
 370
 371     $got = $out->read();
 372     # Remove any warnings about having too few iterations.
 373     $got =~ s/\(warning:[^\)]+\)//gs;
 374     like ($got, qr/timing 10 iterations of\s+Bar\W+Foo\W*?\.\.\./s,
 375       'check title');
 376     # Remove the title
 377     $got =~ s/.*\.\.\.//s;
 378     like ($got, $nop_pattern, 'specify format as nop');
 379     like ($got, $graph_dissassembly, "Should find the output graph somewhere");
 380     check_graph_vs_output ($chart, $got);
 381 }
 382
 383 {
 384     $foo = $bar = 0;
 385     select(OUT);
 386     my $chart = cmpthese( 10, $code_to_test, 'none' ) ;
 387     select(STDOUT);
 388     ok ($foo > 0, "Foo code was run");
 389     ok ($bar > 0, "Bar code was run");
 390
 391     $got = $out->read();
 392     # Remove any warnings about having too few iterations.
 393     $got =~ s/\(warning:[^\)]+\)//gs;
 394     $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning
 395     is ($got, '', "format 'none' should suppress output");
 396     is (ref $chart, 'ARRAY', "output should be an array ref");
 397     # Some of these will go bang if the preceding test fails. There will be
 398     # a big clue as to why, from the previous test's diagnostic
 399     is (ref $chart->[0], 'ARRAY', "output should be an array of arrays");
 400     check_graph (@$chart);
 401 }
 402
 403 {
 404     $foo = $bar = 0;
 405     select(OUT);
 406     my $chart = cmpthese( $results ) ;
 407     select(STDOUT);
 408     is ($foo, 0, "Foo code was not run");
 409     is ($bar, 0, "Bar code was not run");
 410
 411     $got = $out->read();
 412     ok ($got !~ /\.\.\./s, 'check that there is no title');
 413     like ($got, $graph_dissassembly, "Should find the output graph somewhere");
 414     check_graph_vs_output ($chart, $got);
 415 }
 416
 417 {
 418     $foo = $bar = 0;
 419     select(OUT);
 420     my $chart = cmpthese( $results, 'none' ) ;
 421     select(STDOUT);
 422     is ($foo, 0, "Foo code was not run");
 423     is ($bar, 0, "Bar code was not run");
 424
 425     $got = $out->read();
 426     is ($got, '', "'none' should suppress all output");
 427     is (ref $chart, 'ARRAY', "output should be an array ref");
 428     # Some of these will go bang if the preceding test fails. There will be
 429     # a big clue as to why, from the previous test's diagnostic
 430     is (ref $chart->[0], 'ARRAY', "output should be an array of arrays");
 431     check_graph (@$chart);
 432 }
 433
 434 ###}my $out = tie *OUT, 'TieOut'; my ($got); ###
 435
 436 my $debug = tie *STDERR, 'TieOut';
 437
 438 $bar = 0;
 439 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
 440 is ($bar, 5, "benchmarked code was run 5 times");
 441 is ($debug->read(), '', "There was no debug output");
 442
 443 Benchmark->debug(1);
 444
 445 $bar = 0;
 446 select(OUT);
 447 $got = timeit(5, '++$bar');
 448 select(STDOUT);
 449 isa_ok($got, 'Benchmark', "timeit eval");
 450 is ($bar, 5, "benchmarked code was run 5 times");
 451 is ($out->read(), '', "There was no STDOUT output with debug enabled");
 452 isnt ($debug->read(), '', "There was STDERR debug output with debug enabled");
 453
 454 Benchmark->debug(0);
 455
 456 $bar = 0;
 457 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
 458 is ($bar, 5, "benchmarked code was run 5 times");
 459 is ($debug->read(), '', "There was no debug output debug disabled");
 460
 461 undef $debug;
 462 untie *STDERR;
 463
 464 # To check the cache we are poking where we don't belong, inside the namespace.
 465 # The way benchmark is written We can't actually check whehter the cache is
 466 # being used, merely what's become cached.
 467
 468 clearallcache();
 469 my @before_keys = keys %Benchmark::cache;
 470 $bar = 0;
 471 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
 472 is ($bar, 5, "benchmarked code was run 5 times");
 473 my @after5_keys = keys %Benchmark::cache;
 474 $bar = 0;
 475 isa_ok(timeit(10, '++$bar'), 'Benchmark', "timeit eval");
 476 is ($bar, 10, "benchmarked code was run 10 times");
 477 ok (!eq_array ([keys %Benchmark::cache], \@after5_keys), "10 differs from 5");
 478
 479 clearcache(10);
 480 # Hash key order will be the same if there are the same keys.
 481 is_deeply ([keys %Benchmark::cache], \@after5_keys,
 482            "cleared 10, only cached results for 5 should remain");
 483
 484 clearallcache();
 485 is_deeply ([keys %Benchmark::cache], \@before_keys,
 486            "back to square 1 when we clear the cache again?");
 487
 488
 489 package TieOut;
 490
 491 sub TIEHANDLE {
 492     my $class = shift;
 493     bless(\( my $ref = ''), $class);
 494 }
 495
 496 sub PRINT {
 497     my $self = shift;
 498     $$self .= join('', @_);
 499 }
 500
 501 sub PRINTF {
 502     my $self = shift;
 503     $$self .= sprintf shift, @_;
 504 }
 505
 506 sub read {
 507     my $self = shift;
 508     return substr($$self, 0, length($$self), '');
 509 }