Benchmark.t/.pm: deal with short times

The number of iterations to do on various tests was set at 3 or 10
in the first incarnation of the test file 13 years ago, and hasn't
changed since. In the meantime, CPUs have gotten faster. So bump the
iteration count to 100. This makes no appreciable difference to total wall
time for the test file on my newish x86_64 platform, but will hopefully
make tests less likely to be running within the noise of  a single 100Hz
clock tick.

In particular, the NetBSD smokes were quite frequently failing tests 127
and 128, due to the CPU taken to do an empty loop being greater than that
for a full loop, thus leading to negative apparent execution time.  This
was likely to be due to the first taking "1" clock tick and the second
taking "0" ticks. Although this is less likely to happen now that the
iterations has been increased, this commit also adds a check to
Benchmark.pm for a negative apparent execution time, and if detected,
prints a "too few iterations" warning and resets it to zero.

diff --git a/lib/Benchmark.pm b/lib/Benchmark.pm
index 1d272a7..90e54a6 100644 (file)
--- a/lib/Benchmark.pm
+++ b/lib/Benchmark.pm
@@ -904,6 +904,16 @@ sub timethis{
 
     $n = $forn if defined $forn;
 
+    if ($t->elapsed($style) < 0) {
+        # due to clock granularity and variable CPU speed and load,
+        # on quick code with a small number of loops, it's possible for
+        # the empty loop to appear to take longer than the real loop
+        # (e.g. 1 tick verses 0 ticks). This leads to a negative elapsed
+        # time. In this case, floor it at zero, to stop bizarre results.
+        print "            (warning: too few iterations for a reliable count)\n";
+        $t->[$_] = 0 for 1..4;
+    }
+
     # A conservative warning to spot very silly tests.
     # Don't assume that your benchmark is ok simply because
     # you don't get this warning!

diff --git a/lib/Benchmark.t b/lib/Benchmark.t
index 680e50d..080641d 100644 (file)
--- a/lib/Benchmark.t
+++ b/lib/Benchmark.t
@@ -144,7 +144,7 @@ is ($auto, $default, 'timestr ($diff, "auto") matches timestr ($diff)');
 
 my $out = tie *OUT, 'TieOut';
 
-my $iterations = 3;
+my $iterations = 100;
 
 $foo = 0;
 select(OUT);
@@ -447,7 +447,7 @@ sub check_graph {
 {
     $foo = $bar = 0;
     select(OUT);
-    my $chart = cmpthese( 10, $code_to_test, 'nop' ) ;
+    my $chart = cmpthese($iterations, $code_to_test, 'nop' ) ;
     select(STDOUT);
     ok ($foo > 0, "Foo code was run");
     ok ($bar > 0, "Bar code was run");
@@ -455,7 +455,7 @@ sub check_graph {
     $got = $out->read();
     # Remove any warnings about having too few iterations.
     $got =~ s/\(warning:[^\)]+\)//gs;
-    like ($got, qr/timing 10 iterations of\s+Bar\W+Foo\W*?\.\.\./s,
+    like ($got, qr/timing $iterations iterations of\s+Bar\W+Foo\W*?\.\.\./s,
       'check title');
     # Remove the title
     $got =~ s/.*\.\.\.//s;
@@ -467,7 +467,7 @@ sub check_graph {
 {
     $foo = $bar = 0;
     select(OUT);
-    my $chart = cmpthese( 10, $code_to_test, 'none' ) ;
+    my $chart = cmpthese($iterations, $code_to_test, 'none' ) ;
     select(STDOUT);
     ok ($foo > 0, "Foo code was run");
     ok ($bar > 0, "Bar code was run");
@@ -484,10 +484,13 @@ sub check_graph {
     check_graph (@$chart);
 }
 
+# this is a repeat of the above test, but with the timing and charting
+# steps split.
+
 {
     $foo = $bar = 0;
     select(OUT);
-    my $res = timethese( 10, $code_to_test, 'none' ) ;
+    my $res = timethese($iterations, $code_to_test, 'none' ) ;
     my $chart = cmpthese($res, 'none' ) ;
     select(STDOUT);
     ok ($foo > 0, "Foo code was run");