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