t/TEST: collect user, sys cpu times for each testfile

In t/TEST, run times() before and after each testfile, and save diffs
into $timings{$testname}, currently containing $etms only.

When run as HARNESS_TIMER=../../perl make test, (also when HARNESS_TIMER=2 or more)
harness output now looks like this:

t/base/cond ................................................... ok        7 ms     0 ms     0 ms
t/base/if ..................................................... ok        4 ms     0 ms     0 ms
t/base/lex .................................................... ok       13 ms     0 ms     0 ms
t/base/num .................................................... ok        9 ms    10 ms     0 ms
t/base/pat .................................................... ok        4 ms     0 ms    10 ms
t/base/rs ..................................................... ok       14 ms    10 ms     0 ms
t/base/term ................................................... ok       20 ms     0 ms    10 ms
t/base/while .................................................. ok        8 ms     0 ms    10 ms
t/comp/bproto ................................................. ok        9 ms    10 ms     0 ms

The additional timing data is also written into the Storable file:

  'perf' => {
    '../cpan/Archive-Extract/t/01_Archive-Extract.t' => [
      '3916.87417030334',
      '1700',
      '2380'
    ],
    '../cpan/Archive-Tar/t/01_use.t' => [
      '92.1041965484619',
      '70.0000000000003',
      '19.9999999999996'
    ],
    ...

The numbers are: elapsed time, user-time, system-time.  The latter 2
are children-times from times(); self-times are those of the harness,
which are uninteresting.

They often dont add up (in naive sense); ET can be greater than sum of
others, especially if the process blocks on IO, or can be less than
others, if the process forks and both children are busy.  Also, child
times have 10 ms resolution on Linux, other OS or kernel build options
may vary.

Calling times() in harness will likely also collect bogus child data
if 2 testfiles are run in parallel.

diff --git a/t/TEST b/t/TEST
index f8726d9..a691a37 100755 (executable)
--- a/t/TEST
+++ b/t/TEST
@@ -524,8 +524,18 @@ EOT
     my %failed_tests;
 
     while (my $test = shift @tests) {
-        my $test_start_time = $show_elapsed_time ? Time::HiRes::time() : 0;
-
+        my ($test_start_time, @starttimes) = 0;
+       if ($show_elapsed_time) {
+           $test_start_time = Time::HiRes::time();
+           # times() reports usage by TEST, but we want usage of each
+           # testprog it calls, so record accumulated times now,
+           # subtract them out afterwards.  Ideally, we'd take times
+           # in BEGIN/END blocks (giving better visibility of self vs
+           # children of each testprog), but that would require some
+           # IPC to send results back here, or a completely different
+           # collection scheme (Storable isnt tuned for incremental use)
+           @starttimes = times;
+       }
        if ($test =~ /^$/) {
            next;
        }
@@ -729,8 +739,14 @@ EOT
                my ($elapsed, $etms) = ("", 0);
                if ( $show_elapsed_time ) {
                    $etms = (Time::HiRes::time() - $test_start_time) * 1000;
-                   $elapsed = sprintf( " %8.0f ms", $etms);
-                   $timings{$test} = $etms;
+                   $elapsed = sprintf(" %8.0f ms", $etms);
+
+                   my (@endtimes) = times;
+                   $endtimes[$_] -= $starttimes[$_] for 0..$#endtimes;
+                   splice @endtimes, 0, 2;    # drop self/harness times
+                   $_ *= 1000 for @endtimes;  # and scale to ms
+                   $timings{$test} = [$etms,@endtimes];
+                   $elapsed .= sprintf(" %5.0f ms", $_) for @endtimes;
                }
                print "${te}ok$elapsed\n";
                $good_files = $good_files + 1;