This is a live mirror of the Perl 5 development currently hosted at https://github.com/perl/perl5
t/TEST: collect user, sys cpu times for each testfile
authorJim Cromie <jim.cromie@gmail.com>
Sun, 13 Mar 2011 20:13:15 +0000 (14:13 -0600)
committerFather Chrysostomos <sprout@cpan.org>
Sat, 10 Sep 2011 03:16:09 +0000 (20:16 -0700)
commit25a2b27fba4a91d93a7517d10647a68981f2453f
tree340dbcf954b05d43e491bab12cbacb81430736af
parent8e03ad8f6c24ab6b98b196deca21ee507e4773f7
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.
t/TEST