diff mbox series

[RFC] scripts/tap-driver: report "slow" tests (HACK)

Message ID 20191113142101.30280-1-alex.bennee@linaro.org
State New
Headers show
Series [RFC] scripts/tap-driver: report "slow" tests (HACK) | expand

Commit Message

Alex Bennée Nov. 13, 2019, 2:21 p.m. UTC
Some tests seem to run slower on CI systems but we don't really get
visibility of which it is unless we happen to hang the test at the end
of a run. This hacky change exposes "slow" tests in the tap output.

[AJB: my perl is rusty, I'm sure this could be more idiomatic]

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 scripts/tap-driver.pl | 18 +++++++++++++++---
 1 file changed, 15 insertions(+), 3 deletions(-)

Comments

Alex Bennée Nov. 19, 2019, 7:54 a.m. UTC | #1
Alex Bennée <alex.bennee@linaro.org> writes:

> Some tests seem to run slower on CI systems but we don't really get
> visibility of which it is unless we happen to hang the test at the end
> of a run. This hacky change exposes "slow" tests in the tap output.
>
> [AJB: my perl is rusty, I'm sure this could be more idiomatic]
>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

ping? It would be nice to get this or something similar in 4.2

> ---
>  scripts/tap-driver.pl | 18 +++++++++++++++---
>  1 file changed, 15 insertions(+), 3 deletions(-)
>
> diff --git a/scripts/tap-driver.pl b/scripts/tap-driver.pl
> index 6621a5cd671..0fe748d5de6 100755
> --- a/scripts/tap-driver.pl
> +++ b/scripts/tap-driver.pl
> @@ -29,6 +29,7 @@ use strict;
>  use Getopt::Long ();
>  use TAP::Parser;
>  use Term::ANSIColor qw(:constants);
> +use Time::HiRes qw( time );
>
>  my $ME = "tap-driver.pl";
>  my $VERSION = "2018-11-30";
> @@ -111,7 +112,7 @@ sub decorate_result ($);
>  sub extract_tap_comment ($);
>  sub handle_tap_bailout ($);
>  sub handle_tap_plan ($);
> -sub handle_tap_result ($);
> +sub handle_tap_result ($$);
>  sub is_null_string ($);
>  sub main ();
>  sub report ($;$);
> @@ -220,12 +221,18 @@ sub testsuite_error ($)
>    report "ERROR", "- $_[0]";
>  }
>
> -sub handle_tap_result ($)
> +sub handle_tap_result ($$)
>  {
>    $testno++;
>    my $result_obj = shift;
> +  my $time = shift;
>
>    my $test_result = stringify_result_obj $result_obj;
> +
> +  if ($time > 1.0) {
> +    $test_result = $test_result . sprintf(" (%0.1fs)", $time);
> +  }
> +
>    my $string = $result_obj->number;
>
>    my $description = $result_obj->description;
> @@ -312,6 +319,9 @@ sub main ()
>  {
>    my $iterator = TAP::Parser::Iterator::Stream->new(\*STDIN);
>    my $parser = TAP::Parser->new ({iterator => $iterator });
> +  my ($start, $end);
> +
> +  $start = time();
>
>    STDOUT->autoflush(1);
>    while (defined (my $cur = $parser->next))
> @@ -325,7 +335,9 @@ sub main ()
>          }
>        elsif ($cur->is_test)
>          {
> -          handle_tap_result ($cur);
> +          $end = time();
> +          handle_tap_result ($cur, $end - $start);
> +          $start = time();
>          }
>        elsif ($cur->is_bailout)
>          {


--
Alex Bennée
Wainer dos Santos Moschetta Dec. 11, 2019, 8:03 p.m. UTC | #2
On 11/19/19 5:54 AM, Alex Bennée wrote:
> Alex Bennée <alex.bennee@linaro.org> writes:
>
>> Some tests seem to run slower on CI systems but we don't really get
>> visibility of which it is unless we happen to hang the test at the end
>> of a run. This hacky change exposes "slow" tests in the tap output.
>>
>> [AJB: my perl is rusty, I'm sure this could be more idiomatic]
>>
>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ping? It would be nice to get this or something similar in 4.2

I tested `make check` with this patch but I could not notice any 
different on output. Likely none of the tests ran beyond the time 
threshold. At least make check did not crash miserably, so:

Tested-by: Wainer dos Santos Moschetta <wainersm@redhat.com>

>
>> ---
>>   scripts/tap-driver.pl | 18 +++++++++++++++---
>>   1 file changed, 15 insertions(+), 3 deletions(-)
>>
>> diff --git a/scripts/tap-driver.pl b/scripts/tap-driver.pl
>> index 6621a5cd671..0fe748d5de6 100755
>> --- a/scripts/tap-driver.pl
>> +++ b/scripts/tap-driver.pl
>> @@ -29,6 +29,7 @@ use strict;
>>   use Getopt::Long ();
>>   use TAP::Parser;
>>   use Term::ANSIColor qw(:constants);
>> +use Time::HiRes qw( time );
>>
>>   my $ME = "tap-driver.pl";
>>   my $VERSION = "2018-11-30";
>> @@ -111,7 +112,7 @@ sub decorate_result ($);
>>   sub extract_tap_comment ($);
>>   sub handle_tap_bailout ($);
>>   sub handle_tap_plan ($);
>> -sub handle_tap_result ($);
>> +sub handle_tap_result ($$);
>>   sub is_null_string ($);
>>   sub main ();
>>   sub report ($;$);
>> @@ -220,12 +221,18 @@ sub testsuite_error ($)
>>     report "ERROR", "- $_[0]";
>>   }
>>
>> -sub handle_tap_result ($)
>> +sub handle_tap_result ($$)
>>   {
>>     $testno++;
>>     my $result_obj = shift;
>> +  my $time = shift;
>>
>>     my $test_result = stringify_result_obj $result_obj;
>> +
>> +  if ($time > 1.0) {
>> +    $test_result = $test_result . sprintf(" (%0.1fs)", $time);
>> +  }
>> +
>>     my $string = $result_obj->number;
>>
>>     my $description = $result_obj->description;
>> @@ -312,6 +319,9 @@ sub main ()
>>   {
>>     my $iterator = TAP::Parser::Iterator::Stream->new(\*STDIN);
>>     my $parser = TAP::Parser->new ({iterator => $iterator });
>> +  my ($start, $end);
>> +
>> +  $start = time();
>>
>>     STDOUT->autoflush(1);
>>     while (defined (my $cur = $parser->next))
>> @@ -325,7 +335,9 @@ sub main ()
>>           }
>>         elsif ($cur->is_test)
>>           {
>> -          handle_tap_result ($cur);
>> +          $end = time();
>> +          handle_tap_result ($cur, $end - $start);
>> +          $start = time();
>>           }
>>         elsif ($cur->is_bailout)
>>           {
>
> --
> Alex Bennée
>
diff mbox series

Patch

diff --git a/scripts/tap-driver.pl b/scripts/tap-driver.pl
index 6621a5cd671..0fe748d5de6 100755
--- a/scripts/tap-driver.pl
+++ b/scripts/tap-driver.pl
@@ -29,6 +29,7 @@  use strict;
 use Getopt::Long ();
 use TAP::Parser;
 use Term::ANSIColor qw(:constants);
+use Time::HiRes qw( time );
 
 my $ME = "tap-driver.pl";
 my $VERSION = "2018-11-30";
@@ -111,7 +112,7 @@  sub decorate_result ($);
 sub extract_tap_comment ($);
 sub handle_tap_bailout ($);
 sub handle_tap_plan ($);
-sub handle_tap_result ($);
+sub handle_tap_result ($$);
 sub is_null_string ($);
 sub main ();
 sub report ($;$);
@@ -220,12 +221,18 @@  sub testsuite_error ($)
   report "ERROR", "- $_[0]";
 }
 
-sub handle_tap_result ($)
+sub handle_tap_result ($$)
 {
   $testno++;
   my $result_obj = shift;
+  my $time = shift;
 
   my $test_result = stringify_result_obj $result_obj;
+
+  if ($time > 1.0) {
+    $test_result = $test_result . sprintf(" (%0.1fs)", $time);
+  }
+
   my $string = $result_obj->number;
 
   my $description = $result_obj->description;
@@ -312,6 +319,9 @@  sub main ()
 {
   my $iterator = TAP::Parser::Iterator::Stream->new(\*STDIN);
   my $parser = TAP::Parser->new ({iterator => $iterator });
+  my ($start, $end);
+
+  $start = time();
 
   STDOUT->autoflush(1);
   while (defined (my $cur = $parser->next))
@@ -325,7 +335,9 @@  sub main ()
         }
       elsif ($cur->is_test)
         {
-          handle_tap_result ($cur);
+          $end = time();
+          handle_tap_result ($cur, $end - $start);
+          $start = time();
         }
       elsif ($cur->is_bailout)
         {