This is a live mirror of the Perl 5 development currently hosted at https://github.com/perl/perl5
Re: [perl #23207] persistant sideffect involving bitwise xor and substr
[perl5.git] / lib / Benchmark.t
CommitLineData
0e74ff8e
JH
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);
8962dfd6 11use Test::More tests => 173;
0e74ff8e
JH
12
13use Benchmark qw(:all);
14
ab43e786 15my $delta = 0.4;
0e74ff8e
JH
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
95d5be9e 62my $estimate = int (100 * $in_threesecs / 3) / 100;
0e74ff8e
JH
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
ab43e786
NC
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}
0e74ff8e
JH
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 = @_;
23c50b23
NC
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");
0e74ff8e
JH
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) {
23c50b23
NC
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");
0e74ff8e 284 } else {
23c50b23
NC
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");
0e74ff8e
JH
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");
07e88136
JH
295 unless (ok ($slowfast <= 0 && $slowfast >= -100,
296 "slowfast should be less than or equal to zero, and >= -100")) {
2d684b7a 297 print STDERR "# slowfast $slowfast\n";
23c50b23
NC
298 $all_passed = 0;
299 }
300 unless (ok ($fastslow > 0, "fastslow should be > 0")) {
e5967bfd 301 print STDERR "# fastslow $fastslow\n";
23c50b23
NC
302 $all_passed = 0;
303 }
0e74ff8e 304 } else {
23c50b23
NC
305 $all_passed
306 &= is ($slowrate, $fastrate,
307 "slow rate isn't less than fast rate, so should be the same");
620b59a5
JH
308 # In OpenBSD the $slowfast is sometimes a really, really, really
309 # small number less than zero, and this gets stringified as -0.
23c50b23 310 $all_passed
620b59a5 311 &= like ($slowfast, qr/^-?0$/, "slowfast should be zero");
23c50b23 312 $all_passed
620b59a5 313 &= like ($fastslow, qr/^-?0$/, "fastslow should be zero");
0e74ff8e 314 }
23c50b23 315 return $all_passed;
0e74ff8e
JH
316}
317
318sub check_graph_vs_output {
319 my ($chart, $got) = @_;
320 my ( $ratetext, $slowc, $fastc,
321 $slowr, $slowratet, $slowslow, $slowfastt,
322 $fastr, $fastratet, $fastslowt, $fastfast)
323 = $got =~ $graph_dissassembly;
23c50b23
NC
324 my $all_passed
325 = check_graph_consistency ( $ratetext, $slowc, $fastc,
326 $slowr, $slowratet, $slowslow, $slowfastt,
327 $fastr, $fastratet, $fastslowt, $fastfast);
328 $all_passed
329 &= is_deeply ($chart, [['', $ratetext, $slowc, $fastc],
330 [$slowr, $slowratet, $slowslow, $slowfastt],
331 [$fastr, $fastratet, $fastslowt, $fastfast]],
332 "check the chart layout matches the formatted output");
333 unless ($all_passed) {
334 print STDERR "# Something went wrong there. I got this chart:\n";
335 print STDERR "# $_\n" foreach split /\n/, $got;
336 }
0e74ff8e
JH
337}
338
339sub check_graph {
340 my ($title, $row1, $row2) = @_;
341 is (scalar @$title, 4, "Four entries in title row");
342 is (scalar @$row1, 4, "Four entries in first row");
343 is (scalar @$row2, 4, "Four entries in second row");
344 is (shift @$title, '', "First entry of output graph should be ''");
345 check_graph_consistency (@$title, @$row1, @$row2);
346}
347
348{
349 select(OUT);
350 my $start = times;
8962dfd6 351 my $chart = cmpthese( -0.1, { a => "++\$i", b => "\$i = sqrt(\$i++)" }, "auto" ) ;
0e74ff8e
JH
352 my $end = times;
353 select(STDOUT);
354 ok (($end - $start) > 0.05, "benchmarked code ran for over 0.05 seconds");
355
356 $got = $out->read();
357 # Remove any warnings about having too few iterations.
358 $got =~ s/\(warning:[^\)]+\)//gs;
359
360 like ($got, qr/running\W+a\W+b.*?for at least 0\.1 CPU second/s,
361 'check title');
362 # Remove the title
363 $got =~ s/.*\.\.\.//s;
364 like ($got, $default_pattern, 'should find default format somewhere');
365 like ($got, $graph_dissassembly, "Should find the output graph somewhere");
366 check_graph_vs_output ($chart, $got);
367}
368
8962dfd6
A
369# Not giving auto should suppress timethese results.
370{
371 select(OUT);
372 my $start = times;
373 my $chart = cmpthese( -0.1, { a => "++\$i", b => "\$i = sqrt(\$i++)" } ) ;
374 my $end = times;
375 select(STDOUT);
376 ok (($end - $start) > 0.05, "benchmarked code ran for over 0.05 seconds");
377
378 $got = $out->read();
379 # Remove any warnings about having too few iterations.
380 $got =~ s/\(warning:[^\)]+\)//gs;
381
382 unlike ($got, qr/running\W+a\W+b.*?for at least 0\.1 CPU second/s,
383 'should not have title');
384 # Remove the title
385 $got =~ s/.*\.\.\.//s;
386 unlike ($got, $default_pattern, 'should not find default format somewhere');
387 like ($got, $graph_dissassembly, "Should find the output graph somewhere");
388 check_graph_vs_output ($chart, $got);
389}
390
0e74ff8e
JH
391{
392 $foo = $bar = 0;
393 select(OUT);
394 my $chart = cmpthese( 10, $code_to_test, 'nop' ) ;
395 select(STDOUT);
396 ok ($foo > 0, "Foo code was run");
397 ok ($bar > 0, "Bar code was run");
398
399 $got = $out->read();
400 # Remove any warnings about having too few iterations.
401 $got =~ s/\(warning:[^\)]+\)//gs;
402 like ($got, qr/timing 10 iterations of\s+Bar\W+Foo\W*?\.\.\./s,
403 'check title');
404 # Remove the title
405 $got =~ s/.*\.\.\.//s;
406 like ($got, $nop_pattern, 'specify format as nop');
407 like ($got, $graph_dissassembly, "Should find the output graph somewhere");
408 check_graph_vs_output ($chart, $got);
409}
410
411{
412 $foo = $bar = 0;
413 select(OUT);
414 my $chart = cmpthese( 10, $code_to_test, 'none' ) ;
415 select(STDOUT);
416 ok ($foo > 0, "Foo code was run");
417 ok ($bar > 0, "Bar code was run");
418
419 $got = $out->read();
420 # Remove any warnings about having too few iterations.
421 $got =~ s/\(warning:[^\)]+\)//gs;
422 $got =~ s/^[ \t\n]+//s; # Remove all the whitespace from the beginning
423 is ($got, '', "format 'none' should suppress output");
424 is (ref $chart, 'ARRAY', "output should be an array ref");
425 # Some of these will go bang if the preceding test fails. There will be
426 # a big clue as to why, from the previous test's diagnostic
427 is (ref $chart->[0], 'ARRAY', "output should be an array of arrays");
428 check_graph (@$chart);
429}
430
431{
432 $foo = $bar = 0;
433 select(OUT);
434 my $chart = cmpthese( $results ) ;
435 select(STDOUT);
436 is ($foo, 0, "Foo code was not run");
437 is ($bar, 0, "Bar code was not run");
438
439 $got = $out->read();
440 ok ($got !~ /\.\.\./s, 'check that there is no title');
441 like ($got, $graph_dissassembly, "Should find the output graph somewhere");
442 check_graph_vs_output ($chart, $got);
443}
444
445{
446 $foo = $bar = 0;
447 select(OUT);
448 my $chart = cmpthese( $results, 'none' ) ;
449 select(STDOUT);
450 is ($foo, 0, "Foo code was not run");
451 is ($bar, 0, "Bar code was not run");
452
453 $got = $out->read();
454 is ($got, '', "'none' should suppress all output");
455 is (ref $chart, 'ARRAY', "output should be an array ref");
456 # Some of these will go bang if the preceding test fails. There will be
457 # a big clue as to why, from the previous test's diagnostic
458 is (ref $chart->[0], 'ARRAY', "output should be an array of arrays");
459 check_graph (@$chart);
460}
461
462###}my $out = tie *OUT, 'TieOut'; my ($got); ###
463
464my $debug = tie *STDERR, 'TieOut';
465
466$bar = 0;
467isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
468is ($bar, 5, "benchmarked code was run 5 times");
469is ($debug->read(), '', "There was no debug output");
470
471Benchmark->debug(1);
472
473$bar = 0;
474select(OUT);
475$got = timeit(5, '++$bar');
476select(STDOUT);
477isa_ok($got, 'Benchmark', "timeit eval");
478is ($bar, 5, "benchmarked code was run 5 times");
479is ($out->read(), '', "There was no STDOUT output with debug enabled");
480isnt ($debug->read(), '', "There was STDERR debug output with debug enabled");
481
482Benchmark->debug(0);
483
484$bar = 0;
485isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
486is ($bar, 5, "benchmarked code was run 5 times");
487is ($debug->read(), '', "There was no debug output debug disabled");
488
489undef $debug;
490untie *STDERR;
491
492# To check the cache we are poking where we don't belong, inside the namespace.
493# The way benchmark is written We can't actually check whehter the cache is
494# being used, merely what's become cached.
495
496clearallcache();
497my @before_keys = keys %Benchmark::cache;
498$bar = 0;
499isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
500is ($bar, 5, "benchmarked code was run 5 times");
501my @after5_keys = keys %Benchmark::cache;
502$bar = 0;
503isa_ok(timeit(10, '++$bar'), 'Benchmark', "timeit eval");
504is ($bar, 10, "benchmarked code was run 10 times");
505ok (!eq_array ([keys %Benchmark::cache], \@after5_keys), "10 differs from 5");
506
507clearcache(10);
508# Hash key order will be the same if there are the same keys.
509is_deeply ([keys %Benchmark::cache], \@after5_keys,
510 "cleared 10, only cached results for 5 should remain");
511
512clearallcache();
513is_deeply ([keys %Benchmark::cache], \@before_keys,
514 "back to square 1 when we clear the cache again?");
515
516
517package TieOut;
518
519sub TIEHANDLE {
520 my $class = shift;
521 bless(\( my $ref = ''), $class);
522}
523
524sub PRINT {
525 my $self = shift;
526 $$self .= join('', @_);
527}
528
529sub PRINTF {
530 my $self = shift;
531 $$self .= sprintf shift, @_;
532}
533
534sub read {
535 my $self = shift;
536 return substr($$self, 0, length($$self), '');
537}