Test::Harness feature suggestion

In chasing down a bug in the CORE test suite, I wanted 'make
TEST' to
print the TIME next to 'ok' and found that t/TEST already
supported a
way to show the elapsed time though the $HARNESS_TIMER
environment.

I made this change to t/TEST:
--8<---
--- -   2007-10-24 12:16:04.091354000 +0200
+++ t/TEST      2007-10-24 12:15:50.000000000 +0200
 -496,8
+496,12  EOT
        else {
            if ($max) {
                my $elapsed;
-               if ( $show_elapsed_time ) {
-                   $elapsed = sprintf( " %8.0f
ms", (Time::HiRes::time() - $test_start_time) * 1000
);
+               if ( $show_elapsed_time eq "time"
) {
+                   my now = localtime;
+                   $elapsed = sprintf "
%02d:%02d:%02d", (localtime)[2,1,0];
+               }
+               elsif ( $show_elapsed_time ) {
+                   $elapsed = sprintf " %8.0f
ms", (Time::HiRes::time() - $test_start_time) * 1000;
                }
                else {
                    $elapsed = "";
-->8---

but as t/TEST is a somewhat modified descendant of
Harness.pm, I guess
a more generic change might be in order

pc09:/pro/3gl/CPAN/perl-current/t 136 > env
HARNESS_TIMER=0 ./TEST op/ver.t
t/op/ver....ok
All tests successful.
u=0.00  s=0.00  cu=0.02  cs=0.00  scripts=1  tests=53
pc09:/pro/3gl/CPAN/perl-current/t 137 > env
HARNESS_TIMER=1 ./TEST op/ver.t
t/op/ver....ok       26 ms
All tests successful.
u=0.02  s=0.00  cu=0.02  cs=0.00  scripts=1  tests=53
pc09:/pro/3gl/CPAN/perl-current/t 138 > env
HARNESS_TIMER=time ./TEST op/ver.t
t/op/ver....ok 12:18:46
All tests successful.
u=0.02  s=0.00  cu=0.02  cs=0.00  scripts=1  tests=53
pc09:/pro/3gl/CPAN/perl-current/t 139 >

-- 
H.Merijn Brand         Amsterdam Perl Mongers (http://amsterdam.pm.org/
)
using & porting perl 5.6.2, 5.8.x, 5.10.x  on HP-UX
10.20, 11.00, 11.11,
& 11.23, SuSE 10.1 & 10.2, AIX 5.2, and Cygwin.     
 http://qa.perl.org
http://mirrors.de
velooper.com/hpux/            http://www.test-smoke.org
                        http
://www.goldmark.org/jeff/stupid-disclaimers/

On 24 Oct 2007, at 11:19, H.Merijn Brand wrote:

> In chasing down a bug in the CORE test suite, I wanted
'make TEST' to
> print the TIME next to 'ok' and found that t/TEST
already supported a
> way to show the elapsed time though the $HARNESS_TIMER
environment.

With T::H 2.99 you can

$ prove -rb --timer
t/000-load..............1/2 # Testing HTML::Tiny 0.904
t/000-load..............ok       29 ms
t/010-simple............ok       42 ms
t/020-coverage..........ok      307 ms
t/030-tags..............ok       34 ms
t/040-lazy..............ok       31 ms
t/050-validate_tag......ok       27 ms
All tests successful.
Files=6, Tests=1151,  1 wallclock secs ( 0.15 usr  0.04 sys
+  0.42  
cusr  0.05 csys =  0.66 CPU)
Result: PASS

Do you need the need the full time breakdown (user, system
etc)?

If so we could add a verbose timer option.

-- 
Andy Armstrong, Hexten

On Wed, 24 Oct 2007 11:32:27 +0100, Andy Armstrong <nrciss.us> wrote:

> On 24 Oct 2007, at 11:19, H.Merijn Brand wrote:
> 
> > In chasing down a bug in the CORE test suite, I
wanted 'make TEST' to
> > print the TIME next to 'ok' and found that t/TEST
already supported a
> > way to show the elapsed time though the
$HARNESS_TIMER environment.
> 
> With T::H 2.99 you can
> 
> $ prove -rb --timer
> t/000-load..............1/2 # Testing HTML::Tiny 0.904
> t/000-load..............ok       29 ms
> t/010-simple............ok       42 ms
> t/020-coverage..........ok      307 ms
> t/030-tags..............ok       34 ms
> t/040-lazy..............ok       31 ms
> t/050-validate_tag......ok       27 ms
> All tests successful.
> Files=6, Tests=1151,  1 wallclock secs ( 0.15 usr  0.04
sys +  0.42  
> cusr  0.05 csys =  0.66 CPU)
> Result: PASS
> 
> Do you need the need the full time breakdown (user,
system etc)?

No, I needed an absolute time stamp, as in 12:03:58
The test suite didn't cleanup, and I wanted to see which
test
left the garbage behind, and if the 'make test' showed the
time, I could quickly reduce my search to the tests that
matched the absolute time

see the last of my three examples:

pc09:/pro/3gl/CPAN/perl-current/t 138 > env
HARNESS_TIMER=time ./TEST op/ver.t
t/op/ver....ok 12:18:46
               ^^^^^^^^

> If so we could add a verbose timer option.


-- 
H.Merijn Brand         Amsterdam Perl Mongers (http://amsterdam.pm.org/
)
using & porting perl 5.6.2, 5.8.x, 5.10.x  on HP-UX
10.20, 11.00, 11.11,
& 11.23, SuSE 10.1 & 10.2, AIX 5.2, and Cygwin.     
 http://qa.perl.org
http://mirrors.de
velooper.com/hpux/            http://www.test-smoke.org
                        http
://www.goldmark.org/jeff/stupid-disclaimers/

On 24 Oct 2007, at 12:13, H.Merijn Brand wrote:
> see the last of my three examples:
>
> pc09:/pro/3gl/CPAN/perl-current/t 138 > env
HARNESS_TIMER=time ./ 
> TEST op/ver.t
> t/op/ver....ok 12:18:46

Oh, I see. Yes, we can certainly add that option. I'll try
to get it  
done today.

-- 
Andy Armstrong, Hexten

On 24 Oct 2007, at 12:13, H.Merijn Brand wrote:
> pc09:/pro/3gl/CPAN/perl-current/t 138 > env
HARNESS_TIMER=time ./ 
> TEST op/ver.t
> t/op/ver....ok 12:18:46

Now (as of r736 from http://svn.hexten.ne
t/tapx/trunk) the output  
looks like this:

[12:34] andy $ prove -rb --timer
[12:34:45] t/000-load..............1/2 # Testing HTML::Tiny
0.905
[12:34:45] t/000-load..............ok       27 ms
[12:34:45] t/010-simple............ok       41 ms
[12:34:46] t/020-coverage..........ok      306 ms
[12:34:46] t/030-tags..............ok       34 ms
[12:34:46] t/040-lazy..............ok       31 ms
[12:34:46] t/050-validate_tag......ok       28 ms
All tests successful.
Files=6, Tests=1151,  1 wallclock secs ( 0.15 usr  0.04 sys
+  0.41  
cusr  0.05 csys =  0.65 CPU)
Result: PASS

Is that OK?

-- 
Andy Armstrong, Hexten

On 24/10/2007, Andy Armstrong <nrciss.us> wrote:
> On 24 Oct 2007, at 12:13, H.Merijn Brand wrote:
> > pc09:/pro/3gl/CPAN/perl-current/t 138 > env
HARNESS_TIMER=time ./
> > TEST op/ver.t
> > t/op/ver....ok 12:18:46
>
> Now (as of r736 from http://svn.hexten.ne
t/tapx/trunk) the output
> looks like this:
>
> [12:34] andy $ prove -rb --timer
> [12:34:45] t/000-load..............1/2 # Testing
HTML::Tiny 0.905
> [12:34:45] t/000-load..............ok       27 ms
> [12:34:45] t/010-simple............ok       41 ms
> [12:34:46] t/020-coverage..........ok      306 ms

I think that Merijn wanted to have the time, as in HH:MM:SS,
not the
duration. That helps locating what test has spuriously
created
temporary files it failed to cleanup.

On 24 Oct 2007, at 12:41, Rafael Garcia-Suarez wrote:
>> [12:34] andy $ prove -rb --timer
>> [12:34:45] t/000-load..............1/2 # Testing
HTML::Tiny 0.905
>> [12:34:45] t/000-load..............ok       27 ms
>> [12:34:45] t/010-simple............ok       41 ms
>> [12:34:46] t/020-coverage..........ok      306 ms
>
> I think that Merijn wanted to have the time, as in
HH:MM:SS, not the
> duration. That helps locating what test has spuriously
created
> temporary files it failed to cleanup.

Yeah - is the left hand column not that?

-- 
Andy Armstrong, Hexten

On 24/10/2007, Andy Armstrong <nrciss.us> wrote:
> On 24 Oct 2007, at 12:41, Rafael Garcia-Suarez wrote:
> >> [12:34] andy $ prove -rb --timer
> >> [12:34:45] t/000-load..............1/2 #
Testing HTML::Tiny 0.905
> >> [12:34:45] t/000-load..............ok       27
ms
> >> [12:34:45] t/010-simple............ok       41
ms
> >> [12:34:46] t/020-coverage..........ok      306
ms
> >
> > I think that Merijn wanted to have the time, as in
HH:MM:SS, not the
> > duration. That helps locating what test has
spuriously created
> > temporary files it failed to cleanup.
>
> Yeah - is the left hand column not that?

Ah duh. Didn't notice. That was looking too much like my irc
screen.
/me goes back to work &

On 24 Oct 2007, at 12:44, Rafael Garcia-Suarez wrote:
>> Yeah - is the left hand column not that?
>
> Ah duh. Didn't notice. That was looking too much like
my irc screen.
> /me goes back to work &

Possibly slightly confusing that my shell prompt has the
time in it  
too 

-- 
Andy Armstrong, Hexten

On Wed, 24 Oct 2007 12:36:47 +0100, Andy Armstrong <nrciss.us> wrote:

> On 24 Oct 2007, at 12:13, H.Merijn Brand wrote:
> > pc09:/pro/3gl/CPAN/perl-current/t 138 > env
HARNESS_TIMER=time ./ 
> > TEST op/ver.t
> > t/op/ver....ok 12:18:46
> 
> Now (as of r736 from http://svn.hexten.ne
t/tapx/trunk) the output  
> looks like this:
> 
> [12:34] andy $ prove -rb --timer
> [12:34:45] t/000-load..............1/2 # Testing
HTML::Tiny 0.905
> [12:34:45] t/000-load..............ok       27 ms
> [12:34:45] t/010-simple............ok       41 ms
> [12:34:46] t/020-coverage..........ok      306 ms
> [12:34:46] t/030-tags..............ok       34 ms
> [12:34:46] t/040-lazy..............ok       31 ms
> [12:34:46] t/050-validate_tag......ok       28 ms
> All tests successful.
> Files=6, Tests=1151,  1 wallclock secs ( 0.15 usr  0.04
sys +  0.41  
> cusr  0.05 csys =  0.65 CPU)
> Result: PASS
> 
> Is that OK?

Yes. much appreciated.
Please also try to make t/TEST in sync with this new feature

Maybe even add a comment line in the first 10 lines of
t/TEST that
mentions these possibilities

-- 
H.Merijn Brand         Amsterdam Perl Mongers (http://amsterdam.pm.org/
)
using & porting perl 5.6.2, 5.8.x, 5.10.x  on HP-UX
10.20, 11.00, 11.11,
& 11.23, SuSE 10.1 & 10.2, AIX 5.2, and Cygwin.     
 http://qa.perl.org
http://mirrors.de
velooper.com/hpux/            http://www.test-smoke.org
                        http
://www.goldmark.org/jeff/stupid-disclaimers/