Benchmark.t revision 1.1
1#!./perl -w 2 3BEGIN { 4 chdir 't' if -d 't'; 5 @INC = '../lib'; 6} 7 8use warnings; 9use strict; 10use vars qw($foo $bar $baz $ballast); 11use Test::More tests => 159; 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 parenthises to be useful in this :-) 32my $default_pattern = qr/$all_pattern|$noc_pattern/; 33 34my $t0 = new Benchmark; 35isa_ok ($t0, 'Benchmark', "Ensure we can create a benchmark object"); 36 37# We use the benchmark object once we've done some work: 38 39isa_ok(timeit(5, sub {++$foo}), 'Benchmark', "timeit CODEREF"); 40is ($foo, 5, "benchmarked code was run 5 times"); 41 42isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval"); 43is ($bar, 5, "benchmarked code was run 5 times"); 44 45print "# 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. 51my $coderef = sub {$baz += fib($ballast)}; 52 53# The default is three. 54$baz = 0; 55my $threesecs = countit(0, $coderef); 56isa_ok($threesecs, 'Benchmark', "countit 0, CODEREF"); 57isnt ($baz, 0, "benchmarked code was run"); 58my $in_threesecs = $threesecs->iters; 59print "# $in_threesecs iterations\n"; 60ok ($in_threesecs > 0, "iters returned positive iterations"); 61 62my $estimate = int (100 * $in_threesecs / 3) / 100; 63print "# from the 3 second run estimate $estimate iterations in 1 second...\n"; 64$baz = 0; 65my $onesec = countit(1, $coderef); 66isa_ok($onesec, 'Benchmark', "countit 1, CODEREF"); 67isnt ($baz, 0, "benchmarked code was run"); 68my $in_onesec = $onesec->iters; 69print "# $in_onesec iterations\n"; 70ok ($in_onesec > 0, "iters returned positive iterations"); 71 72{ 73 my $difference = $in_onesec - $estimate; 74 my $actual = abs ($difference / $in_onesec); 75 ok ($actual < $delta, "is $in_onesec within $delta of estimate ($estimate)"); 76 print "# $in_onesec is between " . ($delta / 2) . 77 " and $delta of estimate. Not that safe.\n" if $actual > $delta/2; 78} 79 80# I found that the eval'ed version was 3 times faster than the coderef. 81# (now it has a different ballast value) 82$baz = 0; 83my $again = countit(1, '$baz += fib($ballast)'); 84isa_ok($onesec, 'Benchmark', "countit 1, eval"); 85isnt ($baz, 0, "benchmarked code was run"); 86my $in_again = $again->iters; 87print "# $in_again iterations\n"; 88ok ($in_again > 0, "iters returned positive iterations"); 89 90 91my $t1 = new Benchmark; 92isa_ok ($t1, 'Benchmark', "Create another benchmark object now we're finished"); 93 94my $diff = timediff ($t1, $t0); 95isa_ok ($diff, 'Benchmark', "Get the time difference"); 96isa_ok (timesum ($t0, $t1), 'Benchmark', "check timesum"); 97 98my $default = timestr ($diff); 99isnt ($default, '', 'timestr ($diff)'); 100my $auto = timestr ($diff, 'auto'); 101is ($auto, $default, 'timestr ($diff, "auto") matches timestr ($diff)'); 102 103{ 104 my $all = timestr ($diff, 'all'); 105 like ($all, $all_pattern, 'timestr ($diff, "all")'); 106 print "# $all\n"; 107 108 my ($wallclock, $usr, $sys, $cusr, $csys, $cpu) = $all =~ $all_pattern; 109 110 is (timestr ($diff, 'none'), '', "none supresses output"); 111 112 my $noc = timestr ($diff, 'noc'); 113 like ($noc, qr/$wallclock +wallclock secs? +\( *$usr +usr +\+ +$sys +sys += +$cpu +CPU\)/, 'timestr ($diff, "noc")'); 114 115 my $nop = timestr ($diff, 'nop'); 116 like ($nop, qr/$wallclock +wallclock secs? +\( *$cusr +cusr +\+ +$csys +csys += +\d+\.\d\d +CPU\)/, 'timestr ($diff, "nop")'); 117 118 if ($auto eq $noc) { 119 pass ('"auto" is "noc"'); 120 } else { 121 is ($auto, $all, '"auto" isn\'t "noc", so should be eq to "all"'); 122 } 123 124 like (timestr ($diff, 'all', 'E'), 125 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"]'); 126} 127 128my $out = tie *OUT, 'TieOut'; 129 130my $iterations = 3; 131 132$foo = 0; 133select(OUT); 134my $got = timethis($iterations, sub {++$foo}); 135select(STDOUT); 136isa_ok($got, 'Benchmark', "timethis CODEREF"); 137is ($foo, $iterations, "benchmarked code was run $iterations times"); 138 139$got = $out->read(); 140like ($got, qr/^timethis $iterations/, 'default title'); 141like ($got, $default_pattern, 'default format is all or noc'); 142 143$bar = 0; 144select(OUT); 145$got = timethis($iterations, '++$bar'); 146select(STDOUT); 147isa_ok($got, 'Benchmark', "timethis eval"); 148is ($bar, $iterations, "benchmarked code was run $iterations times"); 149 150$got = $out->read(); 151like ($got, qr/^timethis $iterations/, 'default title'); 152like ($got, $default_pattern, 'default format is all or noc'); 153 154my $title = 'lies, damn lies and benchmarks'; 155$foo = 0; 156select(OUT); 157$got = timethis($iterations, sub {++$foo}, $title); 158select(STDOUT); 159isa_ok($got, 'Benchmark', "timethis with title"); 160is ($foo, $iterations, "benchmarked code was run $iterations times"); 161 162$got = $out->read(); 163like ($got, qr/^$title:/, 'specify title'); 164like ($got, $default_pattern, 'default format is all or noc'); 165 166# default is auto, which is all or noc. nop can never match the default 167$foo = 0; 168select(OUT); 169$got = timethis($iterations, sub {++$foo}, $title, 'nop'); 170select(STDOUT); 171isa_ok($got, 'Benchmark', "timethis with format"); 172is ($foo, $iterations, "benchmarked code was run $iterations times"); 173 174$got = $out->read(); 175like ($got, qr/^$title:/, 'specify title'); 176like ($got, $nop_pattern, 'specify format as nop'); 177 178{ 179 $foo = 0; 180 select(OUT); 181 my $start = time; 182 $got = timethis(-2, sub {$foo+= fib($ballast)}, $title, 'none'); 183 my $end = time; 184 select(STDOUT); 185 isa_ok($got, 'Benchmark', 186 "timethis, at least 2 seconds with format 'none'"); 187 ok ($foo > 0, "benchmarked code was run"); 188 ok ($end - $start > 1, "benchmarked code ran for over 1 second"); 189 190 $got = $out->read(); 191 # Remove any warnings about having too few iterations. 192 $got =~ s/\(warning:[^\)]+\)//gs; 193 $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning 194 195 is ($got, '', "format 'none' should suppress output"); 196} 197 198$foo = $bar = $baz = 0; 199select(OUT); 200$got = timethese($iterations, { Foo => sub {++$foo}, Bar => '++$bar', 201 Baz => sub {++$baz} }); 202select(STDOUT); 203is(ref ($got), 'HASH', "timethese should return a hashref"); 204isa_ok($got->{Foo}, 'Benchmark', "Foo value"); 205isa_ok($got->{Bar}, 'Benchmark', "Bar value"); 206isa_ok($got->{Baz}, 'Benchmark', "Baz value"); 207eq_set([keys %$got], [qw(Foo Bar Baz)], 'should be exactly three objects'); 208is ($foo, $iterations, "Foo code was run $iterations times"); 209is ($bar, $iterations, "Bar code was run $iterations times"); 210is ($baz, $iterations, "Baz code was run $iterations times"); 211 212$got = $out->read(); 213# Remove any warnings about having too few iterations. 214$got =~ s/\(warning:[^\)]+\)//gs; 215 216like ($got, qr/timing $iterations iterations of\s+Bar\W+Baz\W+Foo\W*?\.\.\./s, 217 'check title'); 218# Remove the title 219$got =~ s/.*\.\.\.//s; 220like ($got, qr/\bBar\b.*\bBaz\b.*\bFoo\b/s, 'check output is in sorted order'); 221like ($got, $default_pattern, 'should find default format somewhere'); 222 223my $code_to_test = { Foo => sub {$foo+=fib($ballast-2)}, 224 Bar => sub {$bar+=fib($ballast)}}; 225# Keep these for later. 226my $results; 227{ 228 $foo = $bar = 0; 229 select(OUT); 230 my $start = times; 231 $results = timethese(-0.1, $code_to_test, 'none'); 232 my $end = times; 233 select(STDOUT); 234 235 is(ref ($results), 'HASH', "timethese should return a hashref"); 236 isa_ok($results->{Foo}, 'Benchmark', "Foo value"); 237 isa_ok($results->{Bar}, 'Benchmark', "Bar value"); 238 eq_set([keys %$results], [qw(Foo Bar)], 'should be exactly two objects'); 239 ok ($foo > 0, "Foo code was run"); 240 ok ($bar > 0, "Bar code was run"); 241 242 ok (($end - $start) > 0.1, "benchmarked code ran for over 0.1 seconds"); 243 244 $got = $out->read(); 245 # Remove any warnings about having too few iterations. 246 $got =~ s/\(warning:[^\)]+\)//gs; 247 is ($got =~ tr/ \t\n//c, 0, "format 'none' should suppress output"); 248} 249my $graph_dissassembly = 250 qr!^[ \t]+(\S+)[ \t]+(\w+)[ \t]+(\w+)[ \t]* # Title line 251 \n[ \t]*(\w+)[ \t]+([0-9.]+(?:/s)?)[ \t]+(-+)[ \t]+(-?\d+%)[ \t]* 252 \n[ \t]*(\w+)[ \t]+([0-9.]+(?:/s)?)[ \t]+(-?\d+%)[ \t]+(-+)[ \t]*$!xm; 253 254sub check_graph_consistency { 255 my ( $ratetext, $slowc, $fastc, 256 $slowr, $slowratet, $slowslow, $slowfastt, 257 $fastr, $fastratet, $fastslowt, $fastfast) 258 = @_; 259 my $all_passed = 1; 260 $all_passed 261 &= is ($slowc, $slowr, "left col tag should be top row tag"); 262 $all_passed 263 &= is ($fastc, $fastr, "right col tag should be bottom row tag"); 264 $all_passed &= 265 like ($slowslow, qr/^-+/, "should be dash for comparing slow with slow"); 266 $all_passed 267 &= is ($slowslow, $fastfast, "slow v slow should be same as fast v fast"); 268 my $slowrate = $slowratet; 269 my $fastrate = $fastratet; 270 my ($slow_is_rate, $fast_is_rate); 271 unless ($slow_is_rate = $slowrate =~ s!/s!!) { 272 # Slow is expressed as iters per second. 273 $slowrate = 1/$slowrate if $slowrate; 274 } 275 unless ($fast_is_rate = $fastrate =~ s!/s!!) { 276 # Fast is expressed as iters per second. 277 $fastrate = 1/$fastrate if $fastrate; 278 } 279 if ($ratetext =~ /rate/i) { 280 $all_passed 281 &= ok ($slow_is_rate, "slow should be expressed as a rate"); 282 $all_passed 283 &= ok ($fast_is_rate, "fast should be expressed as a rate"); 284 } else { 285 $all_passed &= 286 ok (!$slow_is_rate, "slow should be expressed as a iters per second"); 287 $all_passed &= 288 ok (!$fast_is_rate, "fast should be expressed as a iters per second"); 289 } 290 291 (my $slowfast = $slowfastt) =~ s!%!!; 292 (my $fastslow = $fastslowt) =~ s!%!!; 293 if ($slowrate < $fastrate) { 294 pass ("slow rate is less than fast rate"); 295 unless (ok ($slowfast < 0 && $slowfast >= -100, 296 "slowfast should be less than zero, and >= -100")) { 297 print STDERR "# slowfast $slowfast\n"; 298 $all_passed = 0; 299 } 300 unless (ok ($fastslow > 0, "fastslow should be > 0")) { 301 print STDERR "# fastslow $fastslow\n"; 302 $all_passed = 0; 303 } 304 } else { 305 $all_passed 306 &= is ($slowrate, $fastrate, 307 "slow rate isn't less than fast rate, so should be the same"); 308 $all_passed 309 &= is ($slowfast, 0, "slowfast should be zero"); 310 $all_passed 311 &= is ($fastslow, 0, "fastslow should be zero"); 312 } 313 return $all_passed; 314} 315 316sub check_graph_vs_output { 317 my ($chart, $got) = @_; 318 my ( $ratetext, $slowc, $fastc, 319 $slowr, $slowratet, $slowslow, $slowfastt, 320 $fastr, $fastratet, $fastslowt, $fastfast) 321 = $got =~ $graph_dissassembly; 322 my $all_passed 323 = check_graph_consistency ( $ratetext, $slowc, $fastc, 324 $slowr, $slowratet, $slowslow, $slowfastt, 325 $fastr, $fastratet, $fastslowt, $fastfast); 326 $all_passed 327 &= is_deeply ($chart, [['', $ratetext, $slowc, $fastc], 328 [$slowr, $slowratet, $slowslow, $slowfastt], 329 [$fastr, $fastratet, $fastslowt, $fastfast]], 330 "check the chart layout matches the formatted output"); 331 unless ($all_passed) { 332 print STDERR "# Something went wrong there. I got this chart:\n"; 333 print STDERR "# $_\n" foreach split /\n/, $got; 334 } 335} 336 337sub check_graph { 338 my ($title, $row1, $row2) = @_; 339 is (scalar @$title, 4, "Four entries in title row"); 340 is (scalar @$row1, 4, "Four entries in first row"); 341 is (scalar @$row2, 4, "Four entries in second row"); 342 is (shift @$title, '', "First entry of output graph should be ''"); 343 check_graph_consistency (@$title, @$row1, @$row2); 344} 345 346{ 347 select(OUT); 348 my $start = times; 349 my $chart = cmpthese( -0.1, { a => "++\$i", b => "\$i = sqrt(\$i++)" } ) ; 350 my $end = times; 351 select(STDOUT); 352 ok (($end - $start) > 0.05, "benchmarked code ran for over 0.05 seconds"); 353 354 $got = $out->read(); 355 # Remove any warnings about having too few iterations. 356 $got =~ s/\(warning:[^\)]+\)//gs; 357 358 like ($got, qr/running\W+a\W+b.*?for at least 0\.1 CPU second/s, 359 'check title'); 360 # Remove the title 361 $got =~ s/.*\.\.\.//s; 362 like ($got, $default_pattern, 'should find default format somewhere'); 363 like ($got, $graph_dissassembly, "Should find the output graph somewhere"); 364 check_graph_vs_output ($chart, $got); 365} 366 367{ 368 $foo = $bar = 0; 369 select(OUT); 370 my $chart = cmpthese( 10, $code_to_test, 'nop' ) ; 371 select(STDOUT); 372 ok ($foo > 0, "Foo code was run"); 373 ok ($bar > 0, "Bar code was run"); 374 375 $got = $out->read(); 376 # Remove any warnings about having too few iterations. 377 $got =~ s/\(warning:[^\)]+\)//gs; 378 like ($got, qr/timing 10 iterations of\s+Bar\W+Foo\W*?\.\.\./s, 379 'check title'); 380 # Remove the title 381 $got =~ s/.*\.\.\.//s; 382 like ($got, $nop_pattern, 'specify format as nop'); 383 like ($got, $graph_dissassembly, "Should find the output graph somewhere"); 384 check_graph_vs_output ($chart, $got); 385} 386 387{ 388 $foo = $bar = 0; 389 select(OUT); 390 my $chart = cmpthese( 10, $code_to_test, 'none' ) ; 391 select(STDOUT); 392 ok ($foo > 0, "Foo code was run"); 393 ok ($bar > 0, "Bar code was run"); 394 395 $got = $out->read(); 396 # Remove any warnings about having too few iterations. 397 $got =~ s/\(warning:[^\)]+\)//gs; 398 $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning 399 is ($got, '', "format 'none' should suppress output"); 400 is (ref $chart, 'ARRAY', "output should be an array ref"); 401 # Some of these will go bang if the preceding test fails. There will be 402 # a big clue as to why, from the previous test's diagnostic 403 is (ref $chart->[0], 'ARRAY', "output should be an array of arrays"); 404 check_graph (@$chart); 405} 406 407{ 408 $foo = $bar = 0; 409 select(OUT); 410 my $chart = cmpthese( $results ) ; 411 select(STDOUT); 412 is ($foo, 0, "Foo code was not run"); 413 is ($bar, 0, "Bar code was not run"); 414 415 $got = $out->read(); 416 ok ($got !~ /\.\.\./s, 'check that there is no title'); 417 like ($got, $graph_dissassembly, "Should find the output graph somewhere"); 418 check_graph_vs_output ($chart, $got); 419} 420 421{ 422 $foo = $bar = 0; 423 select(OUT); 424 my $chart = cmpthese( $results, 'none' ) ; 425 select(STDOUT); 426 is ($foo, 0, "Foo code was not run"); 427 is ($bar, 0, "Bar code was not run"); 428 429 $got = $out->read(); 430 is ($got, '', "'none' should suppress all output"); 431 is (ref $chart, 'ARRAY', "output should be an array ref"); 432 # Some of these will go bang if the preceding test fails. There will be 433 # a big clue as to why, from the previous test's diagnostic 434 is (ref $chart->[0], 'ARRAY', "output should be an array of arrays"); 435 check_graph (@$chart); 436} 437 438###}my $out = tie *OUT, 'TieOut'; my ($got); ### 439 440my $debug = tie *STDERR, 'TieOut'; 441 442$bar = 0; 443isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval"); 444is ($bar, 5, "benchmarked code was run 5 times"); 445is ($debug->read(), '', "There was no debug output"); 446 447Benchmark->debug(1); 448 449$bar = 0; 450select(OUT); 451$got = timeit(5, '++$bar'); 452select(STDOUT); 453isa_ok($got, 'Benchmark', "timeit eval"); 454is ($bar, 5, "benchmarked code was run 5 times"); 455is ($out->read(), '', "There was no STDOUT output with debug enabled"); 456isnt ($debug->read(), '', "There was STDERR debug output with debug enabled"); 457 458Benchmark->debug(0); 459 460$bar = 0; 461isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval"); 462is ($bar, 5, "benchmarked code was run 5 times"); 463is ($debug->read(), '', "There was no debug output debug disabled"); 464 465undef $debug; 466untie *STDERR; 467 468# To check the cache we are poking where we don't belong, inside the namespace. 469# The way benchmark is written We can't actually check whehter the cache is 470# being used, merely what's become cached. 471 472clearallcache(); 473my @before_keys = keys %Benchmark::cache; 474$bar = 0; 475isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval"); 476is ($bar, 5, "benchmarked code was run 5 times"); 477my @after5_keys = keys %Benchmark::cache; 478$bar = 0; 479isa_ok(timeit(10, '++$bar'), 'Benchmark', "timeit eval"); 480is ($bar, 10, "benchmarked code was run 10 times"); 481ok (!eq_array ([keys %Benchmark::cache], \@after5_keys), "10 differs from 5"); 482 483clearcache(10); 484# Hash key order will be the same if there are the same keys. 485is_deeply ([keys %Benchmark::cache], \@after5_keys, 486 "cleared 10, only cached results for 5 should remain"); 487 488clearallcache(); 489is_deeply ([keys %Benchmark::cache], \@before_keys, 490 "back to square 1 when we clear the cache again?"); 491 492 493package TieOut; 494 495sub TIEHANDLE { 496 my $class = shift; 497 bless(\( my $ref = ''), $class); 498} 499 500sub PRINT { 501 my $self = shift; 502 $$self .= join('', @_); 503} 504 505sub PRINTF { 506 my $self = shift; 507 $$self .= sprintf shift, @_; 508} 509 510sub read { 511 my $self = shift; 512 return substr($$self, 0, length($$self), ''); 513} 514