Bug #98637 for Test-Harness: [PATCH] subtest timing (a la Benchmark)

The attached patch adds the user+sys+cuser+csys timings for the subtests to the HARNESS_TIMER=1 runs. Before (if run on blead core t/op/h*.t): [08:08:16] op/hash-rt85026.t .. ok 436 ms [08:08:16] op/hash.t .......... ok 87 ms [08:08:16] op/hashassign.t .... ok 62 ms [08:08:16] op/hashwarn.t ...... ok 26 ms [08:08:16] op/heredoc.t ....... ok 509 ms [08:08:17] op/hexfp.t ......... ok 35 ms After: [08:09:48] op/hash-rt85026.t .. ok 261 ms ( 0.01 usr 0.00 sys + 0.08 cusr 0.02 csys = 0.11 CPU) [08:09:48] op/hash.t .......... ok 82 ms ( 0.04 usr 0.00 sys + 0.05 cusr 0.01 csys = 0.10 CPU) [08:09:48] op/hashassign.t .... ok 63 ms ( 0.03 usr 0.00 sys + 0.04 cusr 0.00 csys = 0.07 CPU) [08:09:48] op/hashwarn.t ...... ok 25 ms ( 0.00 usr 0.00 sys + 0.02 cusr 0.01 csys = 0.03 CPU) [08:09:48] op/heredoc.t ....... ok 520 ms ( 0.02 usr 0.00 sys + 0.17 cusr 0.27 csys = 0.46 CPU) [08:09:49] op/hexfp.t ......... ok 36 ms ( 0.01 usr 0.00 sys + 0.03 cusr 0.00 csys = 0.04 CPU)

From 0c60d5d98c8bcd191d7e9f6822662677dc78ad04 Mon Sep 17 00:00:00 2001 From: Jarkko Hietaniemi <jhi@iki.fi> Date: Wed, 20 Aug 2014 22:45:27 -0400 Subject: [PATCH] Enable printing CPU times spent per test. --- cpan/Test-Harness/lib/TAP/Base.pm | 9 ++++++ .../lib/TAP/Formatter/Console/Session.pm | 14 +-------- .../Test-Harness/lib/TAP/Formatter/File/Session.pm | 14 +-------- cpan/Test-Harness/lib/TAP/Formatter/Session.pm | 34 ++++++++++++++++++++++ cpan/Test-Harness/lib/TAP/Parser.pm | 17 +++++++++-- 5 files changed, 60 insertions(+), 28 deletions(-) diff --git a/cpan/Test-Harness/lib/TAP/Base.pm b/cpan/Test-Harness/lib/TAP/Base.pm index 5f60500..18d1a63 100644 --- a/cpan/Test-Harness/lib/TAP/Base.pm +++ b/cpan/Test-Harness/lib/TAP/Base.pm @@ -121,4 +121,13 @@ Return true if the time returned by get_time is high resolution (i.e. if Time::H sub time_is_hires { return GOT_TIME_HIRES } +=head3 C<get_times> + +Return array reference of the four-element list of CPU seconds, +as with L<perlfunc/times>. + +=cut + +sub get_times { return [ times() ] } + 1; diff --git a/cpan/Test-Harness/lib/TAP/Formatter/Console/Session.pm b/cpan/Test-Harness/lib/TAP/Formatter/Console/Session.pm index a075bfa..13cf291 100644 --- a/cpan/Test-Harness/lib/TAP/Formatter/Console/Session.pm +++ b/cpan/Test-Harness/lib/TAP/Formatter/Console/Session.pm @@ -185,19 +185,7 @@ sub _closures { $self->_output_test_failure($parser); } else { - my $time_report = ''; - if ( $formatter->timer ) { - my $start_time = $parser->start_time; - my $end_time = $parser->end_time; - if ( defined $start_time and defined $end_time ) { - my $elapsed = $end_time - $start_time; - $time_report - = $self->time_is_hires - ? sprintf( ' %8d ms', $elapsed * 1000 ) - : sprintf( ' %8s s', $elapsed || '<1' ); - } - } - + my $time_report = $self->time_report($formatter, $parser); $formatter->_output( $self->_make_ok_line($time_report) ); } }, diff --git a/cpan/Test-Harness/lib/TAP/Formatter/File/Session.pm b/cpan/Test-Harness/lib/TAP/Formatter/File/Session.pm index b17a294..6b29588 100644 --- a/cpan/Test-Harness/lib/TAP/Formatter/File/Session.pm +++ b/cpan/Test-Harness/lib/TAP/Formatter/File/Session.pm @@ -85,19 +85,7 @@ sub close_test { $self->_output_test_failure($parser); } else { - my $time_report = ''; - if ( $formatter->timer ) { - my $start_time = $parser->start_time; - my $end_time = $parser->end_time; - if ( defined $start_time and defined $end_time ) { - my $elapsed = $end_time - $start_time; - $time_report - = $self->time_is_hires - ? sprintf( ' %8d ms', $elapsed * 1000 ) - : sprintf( ' %8s s', $elapsed || '<1' ); - } - } - + my $time_report = $self->time_report($formatter, $parser); $formatter->_output( $pretty . ( $self->{results} ? "\n" . $self->{results} : "" ) . $self->_make_ok_line($time_report) ); diff --git a/cpan/Test-Harness/lib/TAP/Formatter/Session.pm b/cpan/Test-Harness/lib/TAP/Formatter/Session.pm index 531185d..6a9bf3e 100644 --- a/cpan/Test-Harness/lib/TAP/Formatter/Session.pm +++ b/cpan/Test-Harness/lib/TAP/Formatter/Session.pm @@ -99,6 +99,11 @@ Called to close a test session. Called by C<close_test> to clear the line showing test progress, or the parallel test ruler, prior to printing the final test result. +=head3 C<time_report> + +Return a formatted string about the elapsed (wall-clock) time +and about the consumed CPU time. + =cut sub header { } @@ -183,4 +188,33 @@ sub _make_ok_line { return "ok$suffix\n"; } +sub time_report { + my ( $self, $formatter, $parser ) = @_; + + my @time_report; + if ( $formatter->timer ) { + my $start_time = $parser->start_time; + my $end_time = $parser->end_time; + if ( defined $start_time and defined $end_time ) { + my $elapsed = $end_time - $start_time; + push @time_report, + $self->time_is_hires + ? sprintf( ' %8d ms', $elapsed * 1000 ) + : sprintf( ' %8s s', $elapsed || '<1' ); + } + my $start_times = $parser->start_times(); + my $end_times = $parser->end_times(); + my $usr = $end_times->[0] - $start_times->[0]; + my $sys = $end_times->[1] - $start_times->[1]; + my $cusr = $end_times->[2] - $start_times->[2]; + my $csys = $end_times->[3] - $start_times->[3]; + push @time_report, + sprintf('(%5.2f usr %5.2f sys + %5.2f cusr %5.2f csys = %5.2f CPU)', + $usr, $sys, $cusr, $csys, + $usr + $sys + $cusr + $csys); + } + + return "@time_report"; +} + 1; diff --git a/cpan/Test-Harness/lib/TAP/Parser.pm b/cpan/Test-Harness/lib/TAP/Parser.pm index 8ff4825..ba3427e 100644 --- a/cpan/Test-Harness/lib/TAP/Parser.pm +++ b/cpan/Test-Harness/lib/TAP/Parser.pm @@ -60,6 +60,8 @@ BEGIN { # making accessors in_todo start_time end_time + start_times + end_times skip_all grammar_class result_factory_class @@ -1007,11 +1009,20 @@ were skipped. =head3 C<start_time> -Returns the time when the Parser was created. +Returns the wall-clock time when the Parser was created. =head3 C<end_time> -Returns the time when the end of TAP input was seen. +Returns the wall-clock time when the end of TAP input was seen. + +=head3 C<start_times> + +Returns the CPU times (like L<perlfunc/times> when the Parser was created. + +=head3 C<end_times> + +Returns the CPU times (like L<perlfunc/times> when the end of TAP +input was seen. =head3 C<has_problems> @@ -1374,6 +1385,7 @@ sub _iter { my $state_table = $self->_make_state_table; $self->start_time( $self->get_time ); + $self->start_times( $self->get_times ); # Make next_state closure my $next_state = sub { @@ -1466,6 +1478,7 @@ sub _finish { my $self = shift; $self->end_time( $self->get_time ); + $self->end_times( $self->get_times ); # Avoid leaks $self->_iterator(undef); -- 2.0.1