[lib/Test.pm] improve accuracy of test timing, pmichaud++ for diagnosing

This change affects the results in docs/test_summary.times that are
created by 'perl tools/test_summary.pl --timing'.  Prior to this
commit the time calculated for each test included the time taken by
print or say to produce the TAP output.  A recent apparent slowdown
in test performace was traced to 'say' taking longer due to added
functionality.  With this commit the time spent producing TAP output
is excluded from test times, making them shorter and more accurate.

lib/Test.pm

@@ -13,6 +13,8 @@ my $num_of_tests_planned;
 my $no_plan = 1;
 my $die_on_fail;
 my $perl6_test_times = ? %*ENV<PERL6_TEST_TIMES>;
+my $time_before = 0E0;
+my $time_after  = 0E0;
 
 ## If done_testing hasn't been run when we hit our END block, we need to know
 ## so that it can be run. This allows compatibility with old tests that use
@@ -44,10 +46,14 @@ multi sub plan($number_of_tests) {
 
         say '1..' ~ $number_of_tests;
     }
-    # Emit two successive timestamps to measure the measurment overhead,
-    # and to eliminate cacheing bias, if it exists, from the first test.
-    say '# t=' ~ nqp::p6box_s(pir::time__n) if $perl6_test_times;
-    say '# t=' ~ nqp::p6box_s(pir::time__n) if $perl6_test_times;
+    # Get two successive timestamps to measure the measurement overhead,
+    # and to reduce bias, if it exists, from the first test time.
+    $time_before = nqp::p6box_n(pir::time__N);
+    $time_after  = nqp::p6box_n(pir::time__N);
+    say '# between two timestamps ' ~
+        ceiling(($time_after-$time_before)*1_000_000) ~ ' microseconds'
+        if $perl6_test_times;
+    $time_before = nqp::p6box_n(pir::time__N);
     # Ideally the time readings above could be made with the expression
     # now.to-posix[0], but the execution time showed by the difference
     # between the two successive readings is far slower than when the
@@ -235,6 +241,8 @@ sub eval_exception($code) {
 }
 
 sub proclaim($cond, $desc) {
+    # exclude the time spent in proclaim from the test time
+    $time_after = nqp::p6box_n(pir::time__N);
     $num_of_tests_run = $num_of_tests_run + 1;
 
     unless $cond {
@@ -248,14 +256,17 @@ sub proclaim($cond, $desc) {
         print $todo_reason;
     }
     print "\n";
-    say '# t=' ~ nqp::p6box_s(pir::time__n) if $perl6_test_times;
+    print "# t=" ~ ceiling(($time_after-$time_before)*1_000_000) ~ "\n"
+        if $perl6_test_times;
 
     if !$cond && $die_on_fail && !$todo_reason {
         die "Test failed.  Stopping test";
     }
     # must clear this between tests
     if $todo_upto_test_num == $num_of_tests_run { $todo_reason = '' }
     $cond;
+    # exclude the time spent in proclaim from the test time
+    $time_before = nqp::p6box_n(pir::time__N);
 }
 
 sub done_testing() is export {

tools/test_summary.pl

@@ -113,14 +113,11 @@
     for (@results) {
         # Pass over the optional line containing "1..$planned"
         if    (/^1\.\.(\d+)/)      { $plan = $1 if $1 > 0; next; }
-        # Handle lines containing timestamps
-        if    (/^# t=(\d+\.\d+)/)  {
-            # Calculate the execution time of each test
-            $time2 = $time1;
-            $time1 = $1;
-            my $microseconds = int( ($time1 - $time2) * 1_000_000 );
+        # Handle lines containing test times
+        if    (/^# t=(\d+)/)  {
+            my $microseconds = $1;
             if ( $testnumber > 0 ) {
-                # Do this only if the timestamp was after a test result
+                # Do this only if the time was after a test result
                 $times[   $testnumber] = $microseconds;
                 $comments[$testnumber] = $test_comment;
                 $testnumber = 0;  # must see require another "ok $n" first