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