This is a live mirror of the Perl 5 development currently hosted at https://github.com/perl/perl5
Benchmark.t: fix skip() call
[perl5.git] / lib / Benchmark.t
index b4d7149..b7d4e7c 100644 (file)
@@ -8,11 +8,11 @@ BEGIN {
 use warnings;
 use strict;
 use vars qw($foo $bar $baz $ballast);
-use Test::More tests => 193;
+use Test::More tests => 197;
 
 use Benchmark qw(:all);
 
-my $delta = 0.4;
+my $DELTA = 0.4;
 
 # Some timing ballast
 sub fib {
@@ -28,9 +28,18 @@ my $Noc_Pattern =
     qr/(\d+) +wallclock secs? +\( *(-?\d+\.\d\d) +usr +\+ +(-?\d+\.\d\d) +sys += +(-?\d+\.\d\d) +CPU\)/;
 my $Nop_Pattern =
     qr/(\d+) +wallclock secs? +\( *(-?\d+\.\d\d) +cusr +\+ +(-?\d+\.\d\d) +csys += +\d+\.\d\d +CPU\)/;
-# Please don't trust the matching parenthises to be useful in this :-)
+# Please don't trust the matching parentheses to be useful in this :-)
 my $Default_Pattern = qr/$All_Pattern|$Noc_Pattern/;
 
+# see if the ratio of two integer values is within (1+$delta)
+
+sub cmp_delta {
+    my ($min, $max, $delta) = @_;
+    ($min, $max) = ($max, $min) if $max < $min;
+    return 0 if $min < 1; # avoid / 0
+    return $max/$min <= (1+$delta);
+}
+
 my $t0 = new Benchmark;
 isa_ok ($t0, 'Benchmark', "Ensure we can create a benchmark object");
 
@@ -42,9 +51,73 @@ is ($foo, 5, "benchmarked code was run 5 times");
 isa_ok(timeit(5, '++$bar'), 'Benchmark', "timeit eval");
 is ($bar, 5, "benchmarked code was run 5 times");
 
-print "# Burning CPU to benchmark things will take time...\n";
+# is coderef called with spurious arguments?
+timeit( 1, sub { $foo = @_ });
+is ($foo, 0, "benchmarked code called without arguments");
+
+
+print "# Burning CPU to see if clock is consistent...\n";
 
+# Run some code for approx 3 secs, then for 1 sec. If the first doesn't
+# take appoex 3 times longer than the second, then skip any tests which
+# require a consistent clock
 
+my $INCONSISTENT_CLOCK = 0;
+my $calibration;
+
+{
+    my ($t0, $t1, $tdelta);
+
+    $t0 = times; 1 while times == $t0; # wait for OS clock to tick
+
+    # guess approx n for code to run for 1 sec
+    my $n = 1;
+    while ($n < 1_000_000_000) { # eventually stop in worst case
+       $t0 = times;
+       fib($ballast) for 1..$n;
+       $t1 = times;
+       $tdelta = ($t1 - $t0);
+       last if ($tdelta) >= 1.0;
+       $n *= 2;
+    }
+    print "# did $n iterations in $tdelta sec\n";
+
+    # adjust n for exactly one second
+    $n /= $tdelta;
+
+    # now run enough loops for approx 3 secs
+
+    $t0 = times; 1 while times == $t0; # wait for OS clock to tick
+    $t0 = times;
+    fib($ballast) for 1..($n*3);
+    $t1 = times;
+    my $td3 = ($t1 - $t0);
+    print "# approx 3 sec delta is $td3 secs\n";
+
+    # now run enough loops for approx 1 sec
+
+    $t0 = times; 1 while times == $t0; # wait for OS clock to tick
+    $t0 = times;
+    fib($ballast) for 1..$n;
+    $t1 = times;
+    my $td1 = ($t1 - $t0);
+    print "# approx 1 sec delta is $td1 secs\n";
+
+    # we use 0.7 of $DELTA so that we err on the side of assuming
+    # a bad clock and skip tests; otherwise we might be just within the
+    # delta here, and just outside the delta on tests, and so get random
+    # failures
+    unless (cmp_delta(3*$td1, $td3, 0.7*$DELTA)) {
+       print "# INCONSISTENT CLOCK! - will skip timing-related tests\n";
+       $INCONSISTENT_CLOCK = 1;
+    }
+    $calibration = $td3/(3*$td1); # for diag output
+
+}
+ok(!$INCONSISTENT_CLOCK, "temporary calibration test");
+
+
+print "# Burning CPU to benchmark things; will take time...\n";
 
 # We need to do something fairly slow in the coderef.
 # Same coderef. Same place in memory.
@@ -56,25 +129,48 @@ my $threesecs = countit(0, $coderef);
 isa_ok($threesecs, 'Benchmark', "countit 0, CODEREF");
 isnt ($baz, 0, "benchmarked code was run");
 my $in_threesecs = $threesecs->iters;
-print "# $in_threesecs iterations\n";
+print "# in_threesecs=$in_threesecs iterations\n";
 ok ($in_threesecs > 0, "iters returned positive iterations");
-
-my $estimate = int (100 * $in_threesecs / 3) / 100;
+my $cpu3 = $threesecs->[1]; # user
+my $sys3 = $threesecs->[2]; # sys
+cmp_ok($cpu3+$sys3, '>=', 3.0, "3s cpu3 is at least 3s");
+my $in_threesecs_adj = $in_threesecs;
+$in_threesecs_adj *= (3/$cpu3); # adjust because may not have run for exactly 3s
+print "# in_threesecs_adj=$in_threesecs_adj adjusted iterations\n";
+
+my $estimate = int (100 * $in_threesecs_adj / 3) / 100;
 print "# from the 3 second run estimate $estimate iterations in 1 second...\n";
 $baz = 0;
 my $onesec = countit(1, $coderef);
 isa_ok($onesec, 'Benchmark', "countit 1, CODEREF");
 isnt ($baz, 0, "benchmarked code was run");
 my $in_onesec = $onesec->iters;
-print "# $in_onesec iterations\n";
+print "# in_onesec=$in_onesec iterations\n";
 ok ($in_onesec > 0, "iters returned positive iterations");
-
-{
-  my $difference = $in_onesec - $estimate;
-  my $actual = abs ($difference / $in_onesec);
-  ok ($actual < $delta, "is $in_onesec within $delta of estimate ($estimate)");
-  print "# $in_onesec is between " . ($delta / 2) .
-    " and $delta of estimate. Not that safe.\n" if $actual > $delta/2;
+my $cpu1 = $onesec->[1]; # user
+my $sys1 = $onesec->[2]; # sys
+cmp_ok($cpu1+$sys1, '>=', 1.0, "is cpu1 is at least 1s");
+my $in_onesec_adj = $in_onesec;
+$in_onesec_adj *= (1/$cpu1); # adjust because may not have run for exactly 1s
+print "# in_onesec_adj=$in_onesec_adj adjusted iterations\n";
+
+SKIP: {
+    skip(1, "INCONSISTENT CLOCK") if $INCONSISTENT_CLOCK;
+
+    ok(cmp_delta($in_onesec_adj, $estimate, $DELTA),
+               "is $in_onesec_adj within $DELTA of estimate ($estimate)?")
+    or do {
+       diag("  in_threesecs     = $in_threesecs");
+       diag("  in_threesecs_adj = $in_threesecs_adj");
+       diag("  cpu3             = $cpu3");
+       diag("  sys3             = $sys3");
+       diag("  estimate         = $estimate");
+       diag("  in_onesec        = $in_onesec");
+       diag("  in_onesec_adj    = $in_onesec_adj");
+       diag("  cpu1             = $cpu1");
+       diag("  sys1             = $sys1");
+       diag("  calibration      = $calibration");
+    };
 }
 
 # I found that the eval'ed version was 3 times faster than the coderef.
@@ -107,10 +203,10 @@ is ($auto, $default, 'timestr ($diff, "auto") matches timestr ($diff)');
 
     my ($wallclock, $usr, $sys, $cusr, $csys, $cpu) = $all =~ $All_Pattern;
 
-    is (timestr ($diff, 'none'), '', "none supresses output");
+    is (timestr ($diff, 'none'), '', "none suppresses output");
 
     my $noc = timestr ($diff, 'noc');
-    like ($noc, qr/$wallclock +wallclock secs? +\( *$usr +usr +\+ +$sys +sys += +$cpu +CPU\)/, 'timestr ($diff, "noc")');
+    like ($noc, qr/$wallclock +wallclock secs? +\( *$usr +usr +\+ +$sys +sys += +\d+\.\d\d +CPU\)/, 'timestr ($diff, "noc")');
 
     my $nop = timestr ($diff, 'nop');
     like ($nop, qr/$wallclock +wallclock secs? +\( *$cusr +cusr +\+ +$csys +csys += +\d+\.\d\d +CPU\)/, 'timestr ($diff, "nop")');
@@ -291,6 +387,7 @@ sub check_graph_consistency {
         $slowr, $slowratet, $slowslow, $slowfastt,
         $fastr, $fastratet, $fastslowt, $fastfast)
         = @_;
+    note("calling check_graph_consistency from line " . (caller(1))[2]);
     my $all_passed = 1;
     $all_passed
       &= is ($slowc, $slowr, "left col tag should be top row tag");
@@ -525,7 +622,7 @@ undef $debug;
 untie *STDERR;
 
 # To check the cache we are poking where we don't belong, inside the namespace.
-# The way benchmark is written We can't actually check whehter the cache is
+# The way benchmark is written we can't actually check whether the cache is
 # being used, merely what's become cached.
 
 clearallcache();
@@ -583,7 +680,7 @@ is_deeply ([keys %Benchmark::Cache], \@before_keys,
 
     foreach my $func (@takes_no_args) {
         eval "$func(42)";
-        like( $@, qr/Too many arguments for Benchmark::$func/, "$func usage: with args" );
+        is( $@, $usage{$func}, "$func usage: with args" );
     }
 }