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 => 196;
  12
  13 use Benchmark qw(:all);
  14
  15 my $delta = 0.4;
  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 parentheses 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 # is coderef called with spurious arguments?
  46 timeit( 1, sub { $foo = @_ });
  47 is ($foo, 0, "benchmarked code called without arguments");
  48
  49
  50 print "# Burning CPU to benchmark things will take time...\n";
  51
  52
  53
  54 # We need to do something fairly slow in the coderef.
  55 # Same coderef. Same place in memory.
  56 my $coderef = sub {$baz += fib($ballast)};
  57
  58 # The default is three.
  59 $baz = 0;
  60 my $threesecs = countit(0, $coderef);
  61 isa_ok($threesecs, 'Benchmark', "countit 0, CODEREF");
  62 isnt ($baz, 0, "benchmarked code was run");
  63 my $in_threesecs = $threesecs->iters;
  64 print "# in_threesecs=$in_threesecs iterations\n";
  65 ok ($in_threesecs > 0, "iters returned positive iterations");
  66 my $cpu3 = $threesecs->[1]; # user
  67 my $sys3 = $threesecs->[2]; # sys
  68 cmp_ok($cpu3+$sys3, '>=', 3.0, "3s cpu3 is at least 3s");
  69 my $in_threesecs_adj = $in_threesecs;
  70 $in_threesecs_adj *= (3/$cpu3); # adjust because may not have run for exactly 3s
  71 print "# in_threesecs_adj=$in_threesecs_adj adjusted iterations\n";
  72
  73 my $estimate = int (100 * $in_threesecs_adj / 3) / 100;
  74 print "# from the 3 second run estimate $estimate iterations in 1 second...\n";
  75 $baz = 0;
  76 my $onesec = countit(1, $coderef);
  77 isa_ok($onesec, 'Benchmark', "countit 1, CODEREF");
  78 isnt ($baz, 0, "benchmarked code was run");
  79 my $in_onesec = $onesec->iters;
  80 print "# in_onesec=$in_onesec iterations\n";
  81 ok ($in_onesec > 0, "iters returned positive iterations");
  82 my $cpu1 = $onesec->[1]; # user
  83 my $sys1 = $onesec->[2]; # sys
  84 cmp_ok($cpu1+$sys1, '>=', 1.0, "is cpu1 is at least 1s");
  85 my $in_onesec_adj = $in_onesec;
  86 $in_onesec_adj *= (1/$cpu1); # adjust because may not have run for exactly 1s
  87 print "# in_onesec_adj=$in_onesec_adj adjusted iterations\n";
  88
  89 {
  90   my $difference = $in_onesec_adj - $estimate;
  91   my $actual = abs ($difference / $in_onesec_adj);
  92   cmp_ok($actual, '<=', $delta, "is $in_onesec_adj within $delta of estimate ($estimate)")
  93     or do {
  94         diag("  in_threesecs     = $in_threesecs");
  95         diag("  in_threesecs_adj = $in_threesecs_adj");
  96         diag("  cpu3             = $cpu3");
  97         diag("  sys3             = $sys3");
  98         diag("  estimate         = $estimate");
  99         diag("  in_onesec        = $in_onesec");
 100         diag("  in_onesec_adj    = $in_onesec_adj");
 101         diag("  cpu1             = $cpu1");
 102         diag("  sys1             = $sys1");
 103     };
 104 }
 105
 106 # I found that the eval'ed version was 3 times faster than the coderef.
 107 # (now it has a different ballast value)
 108 $baz = 0;
 109 my $again = countit(1, '$baz += fib($ballast)');
 110 isa_ok($onesec, 'Benchmark', "countit 1, eval");
 111 isnt ($baz, 0, "benchmarked code was run");
 112 my $in_again = $again->iters;
 113 print "# $in_again iterations\n";
 114 ok ($in_again > 0, "iters returned positive iterations");
 115
 116
 117 my $t1 = new Benchmark;
 118 isa_ok ($t1, 'Benchmark', "Create another benchmark object now we're finished");
 119
 120 my $diff = timediff ($t1, $t0);
 121 isa_ok ($diff, 'Benchmark', "Get the time difference");
 122 isa_ok (timesum ($t0, $t1), 'Benchmark', "check timesum");
 123
 124 my $default = timestr ($diff);
 125 isnt ($default, '', 'timestr ($diff)');
 126 my $auto = timestr ($diff, 'auto');
 127 is ($auto, $default, 'timestr ($diff, "auto") matches timestr ($diff)');
 128
 129 {
 130     my $all = timestr ($diff, 'all');
 131     like ($all, $All_Pattern, 'timestr ($diff, "all")');
 132     print "# $all\n";
 133
 134     my ($wallclock, $usr, $sys, $cusr, $csys, $cpu) = $all =~ $All_Pattern;
 135
 136     is (timestr ($diff, 'none'), '', "none suppresses output");
 137
 138     my $noc = timestr ($diff, 'noc');
 139     like ($noc, qr/$wallclock +wallclock secs? +\( *$usr +usr +\+ +$sys +sys += +\d+\.\d\d +CPU\)/, 'timestr ($diff, "noc")');
 140
 141     my $nop = timestr ($diff, 'nop');
 142     like ($nop, qr/$wallclock +wallclock secs? +\( *$cusr +cusr +\+ +$csys +csys += +\d+\.\d\d +CPU\)/, 'timestr ($diff, "nop")');
 143
 144     if ($auto eq $noc) {
 145         pass ('"auto" is "noc"');
 146     } else {
 147         is ($auto, $all, '"auto" isn\'t "noc", so should be eq to "all"');
 148     }
 149
 150     like (timestr ($diff, 'all', 'E'),
 151           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"]');
 152 }
 153
 154 my $out = tie *OUT, 'TieOut';
 155
 156 my $iterations = 3;
 157
 158 $foo = 0;
 159 select(OUT);
 160 my $got = timethis($iterations, sub {++$foo});
 161 select(STDOUT);
 162 isa_ok($got, 'Benchmark', "timethis CODEREF");
 163 is ($foo, $iterations, "benchmarked code was run $iterations times");
 164
 165 $got = $out->read();
 166 like ($got, qr/^timethis $iterations/, 'default title');
 167 like ($got, $Default_Pattern, 'default format is all or noc');
 168
 169 $bar = 0;
 170 select(OUT);
 171 $got = timethis($iterations, '++$bar');
 172 select(STDOUT);
 173 isa_ok($got, 'Benchmark', "timethis eval");
 174 is ($bar, $iterations, "benchmarked code was run $iterations times");
 175
 176 $got = $out->read();
 177 like ($got, qr/^timethis $iterations/, 'default title');
 178 like ($got, $Default_Pattern, 'default format is all or noc');
 179
 180 my $title = 'lies, damn lies and benchmarks';
 181 $foo = 0;
 182 select(OUT);
 183 $got = timethis($iterations, sub {++$foo}, $title);
 184 select(STDOUT);
 185 isa_ok($got, 'Benchmark', "timethis with title");
 186 is ($foo, $iterations, "benchmarked code was run $iterations times");
 187
 188 $got = $out->read();
 189 like ($got, qr/^$title:/, 'specify title');
 190 like ($got, $Default_Pattern, 'default format is all or noc');
 191
 192 # default is auto, which is all or noc. nop can never match the default
 193 $foo = 0;
 194 select(OUT);
 195 $got = timethis($iterations, sub {++$foo}, $title, 'nop');
 196 select(STDOUT);
 197 isa_ok($got, 'Benchmark', "timethis with format");
 198 is ($foo, $iterations, "benchmarked code was run $iterations times");
 199
 200 $got = $out->read();
 201 like ($got, qr/^$title:/, 'specify title');
 202 like ($got, $Nop_Pattern, 'specify format as nop');
 203
 204 {
 205     $foo = 0;
 206     select(OUT);
 207     my $start = time;
 208     $got = timethis(-2, sub {$foo+= fib($ballast)}, $title, 'none');
 209     my $end = time;
 210     select(STDOUT);
 211     isa_ok($got, 'Benchmark',
 212            "timethis, at least 2 seconds with format 'none'");
 213     ok ($foo > 0, "benchmarked code was run");
 214     ok ($end - $start > 1, "benchmarked code ran for over 1 second");
 215
 216     $got = $out->read();
 217     # Remove any warnings about having too few iterations.
 218     $got =~ s/\(warning:[^\)]+\)//gs;
 219     $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning
 220
 221     is ($got, '', "format 'none' should suppress output");
 222 }
 223
 224 $foo = $bar = $baz = 0;
 225 select(OUT);
 226 $got = timethese($iterations, { Foo => sub {++$foo}, Bar => '++$bar',
 227                                 Baz => sub {++$baz} });
 228 select(STDOUT);
 229 is(ref ($got), 'HASH', "timethese should return a hashref");
 230 isa_ok($got->{Foo}, 'Benchmark', "Foo value");
 231 isa_ok($got->{Bar}, 'Benchmark', "Bar value");
 232 isa_ok($got->{Baz}, 'Benchmark', "Baz value");
 233 eq_set([keys %$got], [qw(Foo Bar Baz)], 'should be exactly three objects');
 234 is ($foo, $iterations, "Foo code was run $iterations times");
 235 is ($bar, $iterations, "Bar code was run $iterations times");
 236 is ($baz, $iterations, "Baz code was run $iterations times");
 237
 238 $got = $out->read();
 239 # Remove any warnings about having too few iterations.
 240 $got =~ s/\(warning:[^\)]+\)//gs;
 241
 242 like ($got, qr/timing $iterations iterations of\s+Bar\W+Baz\W+Foo\W*?\.\.\./s,
 243       'check title');
 244 # Remove the title
 245 $got =~ s/.*\.\.\.//s;
 246 like ($got, qr/\bBar\b.*\bBaz\b.*\bFoo\b/s, 'check output is in sorted order');
 247 like ($got, $Default_Pattern, 'should find default format somewhere');
 248
 249
 250 { # ensure 'use strict' does not leak from Benchmark.pm into benchmarked code
 251     no strict;
 252     select OUT;
 253
 254     eval {
 255         timethese( 1,
 256                    { undeclared_var => q{ $i++; $i-- },
 257                      symbolic_ref   => q{ $bar = 42;
 258                                           $foo = 'bar';
 259                                           $q = ${$foo} },
 260                    },
 261                    'none'
 262                   );
 263
 264     };
 265     is( $@, '', q{no strict leakage in name => 'code'} );
 266
 267     eval {
 268         timethese( 1,
 269                    { undeclared_var => sub { $i++; $i-- },
 270                      symbolic_ref   => sub { $bar = 42;
 271                                              $foo = 'bar';
 272                                              return ${$foo} },
 273                    },
 274                    'none'
 275                  );
 276     };
 277     is( $@, '', q{no strict leakage in name => sub { code }} );
 278
 279     # clear out buffer
 280     $out->read;
 281 }
 282
 283
 284 my $code_to_test =  { Foo => sub {$foo+=fib($ballast-2)},
 285                       Bar => sub {$bar+=fib($ballast)}};
 286 # Keep these for later.
 287 my $results;
 288 {
 289     $foo = $bar = 0;
 290     select(OUT);
 291     my $start = times;
 292     $results = timethese(-0.1, $code_to_test, 'none');
 293     my $end = times;
 294     select(STDOUT);
 295
 296     is(ref ($results), 'HASH', "timethese should return a hashref");
 297     isa_ok($results->{Foo}, 'Benchmark', "Foo value");
 298     isa_ok($results->{Bar}, 'Benchmark', "Bar value");
 299     eq_set([keys %$results], [qw(Foo Bar)], 'should be exactly two objects');
 300     ok ($foo > 0, "Foo code was run");
 301     ok ($bar > 0, "Bar code was run");
 302
 303     ok (($end - $start) > 0.1, "benchmarked code ran for over 0.1 seconds");
 304
 305     $got = $out->read();
 306     # Remove any warnings about having too few iterations.
 307     $got =~ s/\(warning:[^\)]+\)//gs;
 308     is ($got =~ tr/ \t\n//c, 0, "format 'none' should suppress output");
 309 }
 310 my $graph_dissassembly =
 311     qr!^[ \t]+(\S+)[ \t]+(\w+)[ \t]+(\w+)[ \t]*         # Title line
 312     \n[ \t]*(\w+)[ \t]+([0-9.]+(?:/s)?)[ \t]+(-+)[ \t]+(-?\d+%)[ \t]*
 313     \n[ \t]*(\w+)[ \t]+([0-9.]+(?:/s)?)[ \t]+(-?\d+%)[ \t]+(-+)[ \t]*$!xm;
 314
 315 sub check_graph_consistency {
 316     my (        $ratetext, $slowc, $fastc,
 317         $slowr, $slowratet, $slowslow, $slowfastt,
 318         $fastr, $fastratet, $fastslowt, $fastfast)
 319         = @_;
 320     note("calling check_graph_consistency from line " . (caller(1))[2]);
 321     my $all_passed = 1;
 322     $all_passed
 323       &= is ($slowc, $slowr, "left col tag should be top row tag");
 324     $all_passed
 325       &= is ($fastc, $fastr, "right col tag should be bottom row tag");
 326     $all_passed &=
 327       like ($slowslow, qr/^-+/, "should be dash for comparing slow with slow");
 328     $all_passed
 329       &= is ($slowslow, $fastfast, "slow v slow should be same as fast v fast");
 330     my $slowrate = $slowratet;
 331     my $fastrate = $fastratet;
 332     my ($slow_is_rate, $fast_is_rate);
 333     unless ($slow_is_rate = $slowrate =~ s!/s!!) {
 334         # Slow is expressed as iters per second.
 335         $slowrate = 1/$slowrate if $slowrate;
 336     }
 337     unless ($fast_is_rate = $fastrate =~ s!/s!!) {
 338         # Fast is expressed as iters per second.
 339         $fastrate = 1/$fastrate if $fastrate;
 340     }
 341     if ($ratetext =~ /rate/i) {
 342         $all_passed
 343           &= ok ($slow_is_rate, "slow should be expressed as a rate");
 344         $all_passed
 345           &= ok ($fast_is_rate, "fast should be expressed as a rate");
 346     } else {
 347         $all_passed &=
 348           ok (!$slow_is_rate, "slow should be expressed as a iters per second");
 349         $all_passed &=
 350           ok (!$fast_is_rate, "fast should be expressed as a iters per second");
 351     }
 352
 353     (my $slowfast = $slowfastt) =~ s!%!!;
 354     (my $fastslow = $fastslowt) =~ s!%!!;
 355     if ($slowrate < $fastrate) {
 356         pass ("slow rate is less than fast rate");
 357         unless (ok ($slowfast <= 0 && $slowfast >= -100,
 358                     "slowfast should be less than or equal to zero, and >= -100")) {
 359           print STDERR "# slowfast $slowfast\n";
 360           $all_passed = 0;
 361         }
 362         unless (ok ($fastslow > 0, "fastslow should be > 0")) {
 363           print STDERR "# fastslow $fastslow\n";
 364           $all_passed = 0;
 365         }
 366     } else {
 367         $all_passed
 368           &= is ($slowrate, $fastrate,
 369                  "slow rate isn't less than fast rate, so should be the same");
 370         # In OpenBSD the $slowfast is sometimes a really, really, really
 371         # small number less than zero, and this gets stringified as -0.
 372         $all_passed
 373           &= like ($slowfast, qr/^-?0$/, "slowfast should be zero");
 374         $all_passed
 375           &= like ($fastslow, qr/^-?0$/, "fastslow should be zero");
 376     }
 377     return $all_passed;
 378 }
 379
 380 sub check_graph_vs_output {
 381     my ($chart, $got) = @_;
 382     my (        $ratetext, $slowc, $fastc,
 383         $slowr, $slowratet, $slowslow, $slowfastt,
 384         $fastr, $fastratet, $fastslowt, $fastfast)
 385         = $got =~ $graph_dissassembly;
 386     my $all_passed
 387       = check_graph_consistency (        $ratetext, $slowc, $fastc,
 388                                  $slowr, $slowratet, $slowslow, $slowfastt,
 389                                  $fastr, $fastratet, $fastslowt, $fastfast);
 390     $all_passed
 391       &= is_deeply ($chart, [['', $ratetext, $slowc, $fastc],
 392                              [$slowr, $slowratet, $slowslow, $slowfastt],
 393                              [$fastr, $fastratet, $fastslowt, $fastfast]],
 394                     "check the chart layout matches the formatted output");
 395     unless ($all_passed) {
 396       print STDERR "# Something went wrong there. I got this chart:\n";
 397       print STDERR "# $_\n" foreach split /\n/, $got;
 398     }
 399 }
 400
 401 sub check_graph {
 402     my ($title, $row1, $row2) = @_;
 403     is (scalar @$title, 4, "Four entries in title row");
 404     is (scalar @$row1, 4, "Four entries in first row");
 405     is (scalar @$row2, 4, "Four entries in second row");
 406     is (shift @$title, '', "First entry of output graph should be ''");
 407     check_graph_consistency (@$title, @$row1, @$row2);
 408 }
 409
 410 {
 411     select(OUT);
 412     my $start = times;
 413     my $chart = cmpthese( -0.1, { a => "++\$i", b => "\$i = sqrt(\$i++)" }, "auto" ) ;
 414     my $end = times;
 415     select(STDOUT);
 416     ok (($end - $start) > 0.05, "benchmarked code ran for over 0.05 seconds");
 417
 418     $got = $out->read();
 419     # Remove any warnings about having too few iterations.
 420     $got =~ s/\(warning:[^\)]+\)//gs;
 421
 422     like ($got, qr/running\W+a\W+b.*?for at least 0\.1 CPU second/s,
 423           'check title');
 424     # Remove the title
 425     $got =~ s/.*\.\.\.//s;
 426     like ($got, $Default_Pattern, 'should find default format somewhere');
 427     like ($got, $graph_dissassembly, "Should find the output graph somewhere");
 428     check_graph_vs_output ($chart, $got);
 429 }
 430
 431 # Not giving auto should suppress timethese results.
 432 {
 433     select(OUT);
 434     my $start = times;
 435     my $chart = cmpthese( -0.1, { a => "++\$i", b => "\$i = sqrt(\$i++)" } ) ;
 436     my $end = times;
 437     select(STDOUT);
 438     ok (($end - $start) > 0.05, "benchmarked code ran for over 0.05 seconds");
 439
 440     $got = $out->read();
 441     # Remove any warnings about having too few iterations.
 442     $got =~ s/\(warning:[^\)]+\)//gs;
 443
 444     unlike ($got, qr/running\W+a\W+b.*?for at least 0\.1 CPU second/s,
 445           'should not have title');
 446     # Remove the title
 447     $got =~ s/.*\.\.\.//s;
 448     unlike ($got, $Default_Pattern, 'should not find default format somewhere');
 449     like ($got, $graph_dissassembly, "Should find the output graph somewhere");
 450     check_graph_vs_output ($chart, $got);
 451 }
 452
 453 {
 454     $foo = $bar = 0;
 455     select(OUT);
 456     my $chart = cmpthese( 10, $code_to_test, 'nop' ) ;
 457     select(STDOUT);
 458     ok ($foo > 0, "Foo code was run");
 459     ok ($bar > 0, "Bar code was run");
 460
 461     $got = $out->read();
 462     # Remove any warnings about having too few iterations.
 463     $got =~ s/\(warning:[^\)]+\)//gs;
 464     like ($got, qr/timing 10 iterations of\s+Bar\W+Foo\W*?\.\.\./s,
 465       'check title');
 466     # Remove the title
 467     $got =~ s/.*\.\.\.//s;
 468     like ($got, $Nop_Pattern, 'specify format as nop');
 469     like ($got, $graph_dissassembly, "Should find the output graph somewhere");
 470     check_graph_vs_output ($chart, $got);
 471 }
 472
 473 {
 474     $foo = $bar = 0;
 475     select(OUT);
 476     my $chart = cmpthese( 10, $code_to_test, 'none' ) ;
 477     select(STDOUT);
 478     ok ($foo > 0, "Foo code was run");
 479     ok ($bar > 0, "Bar code was run");
 480
 481     $got = $out->read();
 482     # Remove any warnings about having too few iterations.
 483     $got =~ s/\(warning:[^\)]+\)//gs;
 484     $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning
 485     is ($got, '', "format 'none' should suppress output");
 486     is (ref $chart, 'ARRAY', "output should be an array ref");
 487     # Some of these will go bang if the preceding test fails. There will be
 488     # a big clue as to why, from the previous test's diagnostic
 489     is (ref $chart->[0], 'ARRAY', "output should be an array of arrays");
 490     check_graph (@$chart);
 491 }
 492
 493 {
 494     $foo = $bar = 0;
 495     select(OUT);
 496     my $chart = cmpthese( $results ) ;
 497     select(STDOUT);
 498     is ($foo, 0, "Foo code was not run");
 499     is ($bar, 0, "Bar code was not run");
 500
 501     $got = $out->read();
 502     ok ($got !~ /\.\.\./s, 'check that there is no title');
 503     like ($got, $graph_dissassembly, "Should find the output graph somewhere");
 504     check_graph_vs_output ($chart, $got);
 505 }
 506
 507 {
 508     $foo = $bar = 0;
 509     select(OUT);
 510     my $chart = cmpthese( $results, 'none' ) ;
 511     select(STDOUT);
 512     is ($foo, 0, "Foo code was not run");
 513     is ($bar, 0, "Bar code was not run");
 514
 515     $got = $out->read();
 516     is ($got, '', "'none' should suppress all output");
 517     is (ref $chart, 'ARRAY', "output should be an array ref");
 518     # Some of these will go bang if the preceding test fails. There will be
 519     # a big clue as to why, from the previous test's diagnostic
 520     is (ref $chart->[0], 'ARRAY', "output should be an array of arrays");
 521     check_graph (@$chart);
 522 }
 523
 524 ###}my $out = tie *OUT, 'TieOut'; my ($got); ###
 525
 526 my $debug = tie *STDERR, 'TieOut';
 527
 528 $bar = 0;
 529 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
 530 is ($bar, 5, "benchmarked code was run 5 times");
 531 is ($debug->read(), '', "There was no debug output");
 532
 533 Benchmark->debug(1);
 534
 535 $bar = 0;
 536 select(OUT);
 537 $got = timeit(5, '++$bar');
 538 select(STDOUT);
 539 isa_ok($got, 'Benchmark', "timeit eval");
 540 is ($bar, 5, "benchmarked code was run 5 times");
 541 is ($out->read(), '', "There was no STDOUT output with debug enabled");
 542 isnt ($debug->read(), '', "There was STDERR debug output with debug enabled");
 543
 544 Benchmark->debug(0);
 545
 546 $bar = 0;
 547 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
 548 is ($bar, 5, "benchmarked code was run 5 times");
 549 is ($debug->read(), '', "There was no debug output debug disabled");
 550
 551 undef $debug;
 552 untie *STDERR;
 553
 554 # To check the cache we are poking where we don't belong, inside the namespace.
 555 # The way benchmark is written we can't actually check whether the cache is
 556 # being used, merely what's become cached.
 557
 558 clearallcache();
 559 my @before_keys = keys %Benchmark::Cache;
 560 $bar = 0;
 561 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
 562 is ($bar, 5, "benchmarked code was run 5 times");
 563 my @after5_keys = keys %Benchmark::Cache;
 564 $bar = 0;
 565 isa_ok(timeit(10, '++$bar'), 'Benchmark', "timeit eval");
 566 is ($bar, 10, "benchmarked code was run 10 times");
 567 ok (!eq_array ([keys %Benchmark::Cache], \@after5_keys), "10 differs from 5");
 568
 569 clearcache(10);
 570 # Hash key order will be the same if there are the same keys.
 571 is_deeply ([keys %Benchmark::Cache], \@after5_keys,
 572            "cleared 10, only cached results for 5 should remain");
 573
 574 clearallcache();
 575 is_deeply ([keys %Benchmark::Cache], \@before_keys,
 576            "back to square 1 when we clear the cache again?");
 577
 578
 579 {   # Check usage error messages
 580     my %usage = %Benchmark::_Usage;
 581     delete $usage{runloop};  # not public, not worrying about it just now
 582
 583     my @takes_no_args = qw(clearallcache disablecache enablecache);
 584
 585     my %cmpthese = ('forgot {}' => 'cmpthese( 42, foo => sub { 1 } )',
 586                      'not result' => 'cmpthese(42)',
 587                      'array ref'  => 'cmpthese( 42, [ foo => sub { 1 } ] )',
 588                     );
 589     while( my($name, $code) = each %cmpthese ) {
 590         eval $code;
 591         is( $@, $usage{cmpthese}, "cmpthese usage: $name" );
 592     }
 593
 594     my %timethese = ('forgot {}'  => 'timethese( 42, foo => sub { 1 } )',
 595                        'no code'    => 'timethese(42)',
 596                        'array ref'  => 'timethese( 42, [ foo => sub { 1 } ] )',
 597                       );
 598
 599     while( my($name, $code) = each %timethese ) {
 600         eval $code;
 601         is( $@, $usage{timethese}, "timethese usage: $name" );
 602     }
 603
 604
 605     while( my($func, $usage) = each %usage ) {
 606         next if grep $func eq $_, @takes_no_args;
 607         eval "$func()";
 608         is( $@, $usage, "$func usage: no args" );
 609     }
 610
 611     foreach my $func (@takes_no_args) {
 612         eval "$func(42)";
 613         is( $@, $usage{$func}, "$func usage: with args" );
 614     }
 615 }
 616
 617
 618 package TieOut;
 619
 620 sub TIEHANDLE {
 621     my $class = shift;
 622     bless(\( my $ref = ''), $class);
 623 }
 624
 625 sub PRINT {
 626     my $self = shift;
 627     $$self .= join('', @_);
 628 }
 629
 630 sub PRINTF {
 631     my $self = shift;
 632     $$self .= sprintf shift, @_;
 633 }
 634
 635 sub read {
 636     my $self = shift;
 637     return substr($$self, 0, length($$self), '');
 638 }