1#!./perl -w 2 3BEGIN { 4 chdir 't' if -d 't'; 5 @INC = ('../lib'); 6} 7 8use warnings; 9use strict; 10our ($foo, $bar, $baz, $ballast); 11use Test::More; 12 13use Benchmark qw(:all); 14 15my $DELTA = 0.4; 16 17# Some timing ballast 18sub fib { 19 my $n = shift; 20 return $n if $n < 2; 21 fib($n-1) + fib($n-2); 22} 23$ballast = 15; 24 25my $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\)/; 27my $Noc_Pattern = 28 qr/(\d+) +wallclock secs? +\( *(-?\d+\.\d\d) +usr +\+ +(-?\d+\.\d\d) +sys += +(-?\d+\.\d\d) +CPU\)/; 29my $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 :-) 32my $Default_Pattern = qr/$All_Pattern|$Noc_Pattern/; 33 34# see if the ratio of two integer values is within (1+$delta) 35 36sub 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 43my $t0 = new Benchmark; 44isa_ok ($t0, 'Benchmark', "Ensure we can create a benchmark object"); 45 46# We use the benchmark object once we've done some work: 47 48isa_ok(timeit(5, sub {++$foo}), 'Benchmark', "timeit CODEREF"); 49is ($foo, 5, "benchmarked code was run 5 times"); 50 51isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval"); 52is ($bar, 5, "benchmarked code was run 5 times"); 53 54# is coderef called with spurious arguments? 55timeit( 1, sub { $foo = @_ }); 56is ($foo, 0, "benchmarked code called without arguments"); 57 58 59print "# 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. 63my $coderef = sub {$baz += fib($ballast)}; 64 65# The default is three. 66$baz = 0; 67my $threesecs = countit(0, $coderef); 68isa_ok($threesecs, 'Benchmark', "countit 0, CODEREF"); 69isnt ($baz, 0, "benchmarked code was run"); 70my $in_threesecs = $threesecs->iters; 71print "# in_threesecs=$in_threesecs iterations\n"; 72cmp_ok($in_threesecs, '>', 0, "iters returned positive iterations"); 73my $cpu3 = $threesecs->[1]; # user 74my $sys3 = $threesecs->[2]; # sys 75cmp_ok($cpu3+$sys3, '>=', 3.0, "3s cpu3 is at least 3s"); 76my $in_threesecs_adj = $in_threesecs; 77$in_threesecs_adj *= (3/$cpu3); # adjust because may not have run for exactly 3s 78print "# in_threesecs_adj=$in_threesecs_adj adjusted iterations\n"; 79 80my $estimate = int (100 * $in_threesecs_adj / 3) / 100; 81print "# from the 3 second run estimate $estimate iterations in 1 second...\n"; 82$baz = 0; 83my $onesec = countit(1, $coderef); 84isa_ok($onesec, 'Benchmark', "countit 1, CODEREF"); 85isnt ($baz, 0, "benchmarked code was run"); 86my $in_onesec = $onesec->iters; 87print "# in_onesec=$in_onesec iterations\n"; 88cmp_ok($in_onesec, '>', 0, "iters returned positive iterations"); 89my $cpu1 = $onesec->[1]; # user 90my $sys1 = $onesec->[2]; # sys 91cmp_ok($cpu1+$sys1, '>=', 1.0, "is cpu1 is at least 1s"); 92my $in_onesec_adj = $in_onesec; 93$in_onesec_adj *= (1/$cpu1); # adjust because may not have run for exactly 1s 94print "# 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; 100my $again = countit(1, '$baz += fib($ballast)'); 101isa_ok($onesec, 'Benchmark', "countit 1, eval"); 102isnt ($baz, 0, "benchmarked code was run"); 103my $in_again = $again->iters; 104print "# $in_again iterations\n"; 105cmp_ok($in_again, '>', 0, "iters returned positive iterations"); 106 107 108my $t1 = new Benchmark; 109isa_ok ($t1, 'Benchmark', "Create another benchmark object now we're finished"); 110 111my $diff = timediff ($t1, $t0); 112isa_ok ($diff, 'Benchmark', "Get the time difference"); 113isa_ok (timesum ($t0, $t1), 'Benchmark', "check timesum"); 114 115my $default = timestr ($diff); 116isnt ($default, '', 'timestr ($diff)'); 117my $auto = timestr ($diff, 'auto'); 118is ($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 145my $out = tie *OUT, 'TieOut'; 146 147my $iterations = 100; 148 149$foo = 0; 150select(OUT); 151my $got = timethis($iterations, sub {++$foo}); 152select(STDOUT); 153isa_ok($got, 'Benchmark', "timethis CODEREF"); 154is ($foo, $iterations, "benchmarked code was run $iterations times"); 155 156$got = $out->read(); 157like ($got, qr/^timethis $iterations/, 'default title'); 158like ($got, $Default_Pattern, 'default format is all or noc'); 159 160$bar = 0; 161select(OUT); 162$got = timethis($iterations, '++$bar'); 163select(STDOUT); 164isa_ok($got, 'Benchmark', "timethis eval"); 165is ($bar, $iterations, "benchmarked code was run $iterations times"); 166 167$got = $out->read(); 168like ($got, qr/^timethis $iterations/, 'default title'); 169like ($got, $Default_Pattern, 'default format is all or noc'); 170 171my $title = 'lies, damn lies and benchmarks'; 172$foo = 0; 173select(OUT); 174$got = timethis($iterations, sub {++$foo}, $title); 175select(STDOUT); 176isa_ok($got, 'Benchmark', "timethis with title"); 177is ($foo, $iterations, "benchmarked code was run $iterations times"); 178 179$got = $out->read(); 180like ($got, qr/^$title:/, 'specify title'); 181like ($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; 185select(OUT); 186$got = timethis($iterations, sub {++$foo}, $title, 'nop'); 187select(STDOUT); 188isa_ok($got, 'Benchmark', "timethis with format"); 189is ($foo, $iterations, "benchmarked code was run $iterations times"); 190 191$got = $out->read(); 192like ($got, qr/^$title:/, 'specify title'); 193like ($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 cmp_ok($foo, '>', 0, "benchmarked code was run"); 205 cmp_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; 216select(OUT); 217$got = timethese($iterations, { Foo => sub {++$foo}, Bar => '++$bar', 218 Baz => sub {++$baz} }); 219select(STDOUT); 220is(ref ($got), 'HASH', "timethese should return a hashref"); 221isa_ok($got->{Foo}, 'Benchmark', "Foo value"); 222isa_ok($got->{Bar}, 'Benchmark', "Bar value"); 223isa_ok($got->{Baz}, 'Benchmark', "Baz value"); 224is_deeply([sort keys %$got], [sort qw(Foo Bar Baz)], 'should be exactly three objects'); 225is ($foo, $iterations, "Foo code was run $iterations times"); 226is ($bar, $iterations, "Bar code was run $iterations times"); 227is ($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 233like ($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; 237like ($got, qr/\bBar\b.*\bBaz\b.*\bFoo\b/s, 'check output is in sorted order'); 238like ($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 275my $code_to_test = { Foo => sub {$foo+=fib($ballast-2)}, 276 Bar => sub {$bar+=fib($ballast)}}; 277# Keep these for later. 278my $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 is_deeply([sort keys %$results], [sort qw(Foo Bar)], 'should be exactly two objects'); 291 cmp_ok($foo, '>', 0, "Foo code was run"); 292 cmp_ok($bar, '>', 0, "Bar code was run"); 293 294 cmp_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} 301my $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 306sub 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 diag("slowfast=$slowfast"); 351 $all_passed = 0; 352 } 353 unless (cmp_ok($fastslow, '>', 0, "fastslow should be > 0")) { 354 $all_passed = 0; 355 } 356 } else { 357 $all_passed 358 &= is ($slowrate, $fastrate, 359 "slow rate isn't less than fast rate, so should be the same"); 360 # In OpenBSD the $slowfast is sometimes a really, really, really 361 # small number less than zero, and this gets stringified as -0. 362 $all_passed 363 &= like ($slowfast, qr/^-?0$/, "slowfast should be zero"); 364 $all_passed 365 &= like ($fastslow, qr/^-?0$/, "fastslow should be zero"); 366 } 367 return $all_passed; 368} 369 370sub check_graph_vs_output { 371 my ($chart, $got) = @_; 372 my ( $ratetext, $slowc, $fastc, 373 $slowr, $slowratet, $slowslow, $slowfastt, 374 $fastr, $fastratet, $fastslowt, $fastfast) 375 = $got =~ $graph_dissassembly; 376 my $all_passed 377 = check_graph_consistency ( $ratetext, $slowc, $fastc, 378 $slowr, $slowratet, $slowslow, $slowfastt, 379 $fastr, $fastratet, $fastslowt, $fastfast); 380 $all_passed 381 &= is_deeply ($chart, [['', $ratetext, $slowc, $fastc], 382 [$slowr, $slowratet, $slowslow, $slowfastt], 383 [$fastr, $fastratet, $fastslowt, $fastfast]], 384 "check the chart layout matches the formatted output"); 385 unless ($all_passed) { 386 diag("Something went wrong there. I got this chart:\n$got"); 387 } 388} 389 390sub check_graph { 391 my ($title, $row1, $row2) = @_; 392 is (scalar @$title, 4, "Four entries in title row"); 393 is (scalar @$row1, 4, "Four entries in first row"); 394 is (scalar @$row2, 4, "Four entries in second row"); 395 is (shift @$title, '', "First entry of output graph should be ''"); 396 check_graph_consistency (@$title, @$row1, @$row2); 397} 398 399{ 400 select(OUT); 401 my $start = times; 402 my $chart = cmpthese( -0.1, { a => "\$i = sqrt(\$i++) * sqrt(\$i) for 1..10", 403 b => "\$i = sqrt(\$i++)", 404 }, "auto" ) ; 405 my $end = times; 406 select(STDOUT); 407 cmp_ok($end - $start, '>', 0.05, 408 "benchmarked code ran for over 0.05 seconds"); 409 410 $got = $out->read(); 411 # Remove any warnings about having too few iterations. 412 $got =~ s/\(warning:[^\)]+\)//gs; 413 414 like ($got, qr/running\W+a\W+b.*?for at least 0\.1 CPU second/s, 415 'check title'); 416 # Remove the title 417 $got =~ s/.*\.\.\.//s; 418 like ($got, $Default_Pattern, 'should find default format somewhere'); 419 like ($got, $graph_dissassembly, "Should find the output graph somewhere"); 420 check_graph_vs_output ($chart, $got); 421} 422 423# Not giving auto should suppress timethese results. 424{ 425 select(OUT); 426 my $start = times; 427 my $chart = cmpthese( -0.1, { a => "\$i = sqrt(\$i++) * sqrt(\$i) for 1..10", 428 b => "\$i = sqrt(\$i++)" }); 429 my $end = times; 430 select(STDOUT); 431 cmp_ok($end - $start, '>', 0.05, 432 "benchmarked code ran for over 0.05 seconds"); 433 434 $got = $out->read(); 435 # Remove any warnings about having too few iterations. 436 $got =~ s/\(warning:[^\)]+\)//gs; 437 438 unlike ($got, qr/running\W+a\W+b.*?for at least 0\.1 CPU second/s, 439 'should not have title'); 440 # Remove the title 441 $got =~ s/.*\.\.\.//s; 442 unlike ($got, $Default_Pattern, 'should not find default format somewhere'); 443 like ($got, $graph_dissassembly, "Should find the output graph somewhere"); 444 check_graph_vs_output ($chart, $got); 445} 446 447{ 448 $foo = $bar = 0; 449 select(OUT); 450 my $chart = cmpthese($iterations, $code_to_test, 'nop' ) ; 451 select(STDOUT); 452 cmp_ok($foo, '>', 0, "Foo code was run"); 453 cmp_ok($bar, '>', 0, "Bar code was run"); 454 455 $got = $out->read(); 456 # Remove any warnings about having too few iterations. 457 $got =~ s/\(warning:[^\)]+\)//gs; 458 like ($got, qr/timing $iterations iterations of\s+Bar\W+Foo\W*?\.\.\./s, 459 'check title'); 460 # Remove the title 461 $got =~ s/.*\.\.\.//s; 462 like ($got, $Nop_Pattern, 'specify format as nop'); 463 like ($got, $graph_dissassembly, "Should find the output graph somewhere"); 464 check_graph_vs_output ($chart, $got); 465} 466 467{ 468 $foo = $bar = 0; 469 select(OUT); 470 my $chart = cmpthese($iterations, $code_to_test, 'none' ) ; 471 select(STDOUT); 472 cmp_ok($foo, '>', 0, "Foo code was run"); 473 cmp_ok($bar, '>', 0, "Bar code was run"); 474 475 $got = $out->read(); 476 # Remove any warnings about having too few iterations. 477 $got =~ s/\(warning:[^\)]+\)//gs; 478 $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning 479 is ($got, '', "format 'none' should suppress output"); 480 is (ref $chart, 'ARRAY', "output should be an array ref"); 481 # Some of these will go bang if the preceding test fails. There will be 482 # a big clue as to why, from the previous test's diagnostic 483 is (ref $chart->[0], 'ARRAY', "output should be an array of arrays"); 484 check_graph (@$chart); 485} 486 487# this is a repeat of the above test, but with the timing and charting 488# steps split. 489 490{ 491 $foo = $bar = 0; 492 select(OUT); 493 my $res = timethese($iterations, $code_to_test, 'none' ) ; 494 my $chart = cmpthese($res, 'none' ) ; 495 select(STDOUT); 496 cmp_ok($foo, '>', 0, "Foo code was run"); 497 cmp_ok($bar, '>', 0, "Bar code was run"); 498 499 $got = $out->read(); 500 # Remove any warnings about having too few iterations. 501 $got =~ s/\(warning:[^\)]+\)//gs; 502 $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning 503 is ($got, '', "format 'none' should suppress output"); 504 is (ref $chart, 'ARRAY', "output should be an array ref"); 505 # Some of these will go bang if the preceding test fails. There will be 506 # a big clue as to why, from the previous test's diagnostic 507 is (ref $chart->[0], 'ARRAY', "output should be an array of arrays"); 508 use Data::Dumper; 509 check_graph(@$chart) 510 or diag(Data::Dumper->Dump([$res, $chart], ['$res', '$chart'])); 511} 512 513{ 514 $foo = $bar = 0; 515 select(OUT); 516 my $chart = cmpthese( $results ) ; 517 select(STDOUT); 518 is ($foo, 0, "Foo code was not run"); 519 is ($bar, 0, "Bar code was not run"); 520 521 $got = $out->read(); 522 unlike($got, qr/\.\.\./s, 'check that there is no title'); 523 like ($got, $graph_dissassembly, "Should find the output graph somewhere"); 524 check_graph_vs_output ($chart, $got); 525} 526 527{ 528 $foo = $bar = 0; 529 select(OUT); 530 my $chart = cmpthese( $results, 'none' ) ; 531 select(STDOUT); 532 is ($foo, 0, "Foo code was not run"); 533 is ($bar, 0, "Bar code was not run"); 534 535 $got = $out->read(); 536 is ($got, '', "'none' should suppress all output"); 537 is (ref $chart, 'ARRAY', "output should be an array ref"); 538 # Some of these will go bang if the preceding test fails. There will be 539 # a big clue as to why, from the previous test's diagnostic 540 is (ref $chart->[0], 'ARRAY', "output should be an array of arrays"); 541 check_graph (@$chart); 542} 543 544###}my $out = tie *OUT, 'TieOut'; my ($got); ### 545 546my $debug = tie *STDERR, 'TieOut'; 547 548$bar = 0; 549isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval"); 550is ($bar, 5, "benchmarked code was run 5 times"); 551is ($debug->read(), '', "There was no debug output"); 552 553Benchmark->debug(1); 554 555$bar = 0; 556select(OUT); 557$got = timeit(5, '++$bar'); 558select(STDOUT); 559isa_ok($got, 'Benchmark', "timeit eval"); 560is ($bar, 5, "benchmarked code was run 5 times"); 561is ($out->read(), '', "There was no STDOUT output with debug enabled"); 562isnt ($debug->read(), '', "There was STDERR debug output with debug enabled"); 563 564Benchmark->debug(0); 565 566$bar = 0; 567isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval"); 568is ($bar, 5, "benchmarked code was run 5 times"); 569is ($debug->read(), '', "There was no debug output debug disabled"); 570 571undef $debug; 572untie *STDERR; 573 574# To check the cache we are poking where we don't belong, inside the namespace. 575# The way benchmark is written we can't actually check whether the cache is 576# being used, merely what's become cached. 577 578clearallcache(); 579my @before_keys = keys %Benchmark::Cache; 580$bar = 0; 581isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval"); 582is ($bar, 5, "benchmarked code was run 5 times"); 583my @after5_keys = keys %Benchmark::Cache; 584$bar = 0; 585isa_ok(timeit(10, '++$bar'), 'Benchmark', "timeit eval"); 586is ($bar, 10, "benchmarked code was run 10 times"); 587cmp_ok (scalar keys %Benchmark::Cache, '>', scalar @after5_keys, "10 differs from 5"); 588 589clearcache(10); 590# Hash key order will be the same if there are the same keys. 591is_deeply ([keys %Benchmark::Cache], \@after5_keys, 592 "cleared 10, only cached results for 5 should remain"); 593 594clearallcache(); 595is_deeply ([keys %Benchmark::Cache], \@before_keys, 596 "back to square 1 when we clear the cache again?"); 597 598 599{ # Check usage error messages 600 my %usage = %Benchmark::_Usage; 601 delete $usage{runloop}; # not public, not worrying about it just now 602 603 my @takes_no_args = qw(clearallcache disablecache enablecache); 604 605 my %cmpthese = ('forgot {}' => 'cmpthese( 42, foo => sub { 1 } )', 606 'not result' => 'cmpthese(42)', 607 'array ref' => 'cmpthese( 42, [ foo => sub { 1 } ] )', 608 ); 609 while( my($name, $code) = each %cmpthese ) { 610 eval $code; 611 is( $@, $usage{cmpthese}, "cmpthese usage: $name" ); 612 } 613 614 my %timethese = ('forgot {}' => 'timethese( 42, foo => sub { 1 } )', 615 'no code' => 'timethese(42)', 616 'array ref' => 'timethese( 42, [ foo => sub { 1 } ] )', 617 ); 618 619 while( my($name, $code) = each %timethese ) { 620 eval $code; 621 is( $@, $usage{timethese}, "timethese usage: $name" ); 622 } 623 624 625 while( my($func, $usage) = each %usage ) { 626 next if grep $func eq $_, @takes_no_args; 627 eval "$func()"; 628 is( $@, $usage, "$func usage: no args" ); 629 } 630 631 foreach my $func (@takes_no_args) { 632 eval "$func(42)"; 633 is( $@, $usage{$func}, "$func usage: with args" ); 634 } 635} 636 637done_testing(); 638 639package TieOut; 640 641sub TIEHANDLE { 642 my $class = shift; 643 bless(\( my $ref = ''), $class); 644} 645 646sub PRINT { 647 my $self = shift; 648 $$self .= join('', @_); 649} 650 651sub PRINTF { 652 my $self = shift; 653 $$self .= sprintf shift, @_; 654} 655 656sub read { 657 my $self = shift; 658 return substr($$self, 0, length($$self), ''); 659} 660