We have a project where we run a couple of tests with a duration of around 3 hours. And I have observed that a lot of minutes are lost in the step of generation the results. For example: I have this script harness.pl

use strict;
use TAP::Harness;
use TAP::Formatter::HTML;
use TAP::Formatter::Console;

# Define Tests
my $tests = {
    "test_1" => {
        test    => 'script.t',
        args    => ['--server', "server_1"]
    },
    # "test_2" => {
        # test  => 'script.t',
        # args  => ['--server', "server_2"]
    # },
};

# Get arguments
my $test_args = {};
$test_args->{$_} = $tests->{$_}->{args} foreach (sort keys %$tests);

# Define formatter
# my $fmt = TAP::Formatter::HTML->new();
# $fmt->output_file( "report.html" );
my $fmt = TAP::Formatter::Console->new({verbosity=>1});


# Start testing
my $harness = TAP::Harness->new( {
        test_args => $test_args,
        formatter => $fmt,
        merge => 1,
        jobs => 1,
    } );

my $result = $harness->runtests(get_tests($tests));

print( "$0 Run Time: " . ( time - $^T ) . " second(s).\n");
print "Passed: ". scalar $result->passed . "\n";
print "Failed: ". scalar $result->failed . "\n";
print "Errors: ". scalar $result->has_errors . "\n";


sub get_tests{
    
    my ($tests) = @_;
    
    my @tests_to_run;
    TEST: foreach my $test (sort keys %$tests){
        # some filtering...
        push @tests_to_run,  [$tests->{$test}->{test}, $test] 
    }
    # some prints...
    return @tests_to_run;
}

And a couple of test, lets take an example of the following script.:

use strict;
use warnings;

use Test::More;
use Getopt::Long qw(GetOptions);


my ($server);
GetOptions(
    'server|s=s'            => \$server,
) or die "[ERROR] Invalid options passed to $0\n";


my $number_of_tests = 100000;
plan tests => 2 + $number_of_tests;


ok (1, "start");
foreach my $test_nr (0..$number_of_tests-1){
    ok(1,"Test numbber: $test_nr in $server");
}
ok ($server eq 'server_1', "Finished");
done_testing;
print( "$0 Run Time: " . ( time - $^T ) . " second(s).\n");

Now I run the tests with the reports of HTML:

# Define formatter
my $fmt = TAP::Formatter::HTML->new();
$fmt->output_file( "report.html" );

And I get the following results:

ok 100002 - Finished
script.t Run Time: 34 second(s). harness.pl Run Time: 42 second(s).
Passed: 100002
Failed: 0
Errors: 0
So 8 seconds after finishing the script.

After that I tried with the default console formatter:

# Define formatter
my $fmt = TAP::Formatter::Console->new({verbosity=>1});

And the result:

ok 100002 - Finished
script.t Run Time: 34 second(s).
ok
All tests successful.
Files=1, Tests=100002, 34 wallclock secs (16.20 usr + 3.61 sys = 19.81 CPU)
Result: PASS
harness.pl Run Time: 34 second(s).
Passed: 100002
Failed: 0
Errors: 0

So this looks quite good, this makes me think that the issue comes from creating a really big HTML report which in this example would generate a 13,854 KB HTML file.

So I go outside of this simple example to my project. And run a simplifed version my test which generates a report like the following: enter image description here As you can see it is not a cray amount of tests, just around 35 with a file of 35 KB I don't think anything which could have many computing issues.

And then I look at the logs with the same structure where I print the last line of the script and I get this cray difference of time:

t/long-test.t Run Time: 117 second(s).
# Looks like you failed 2 tests of 34.
Passed: 32
Failed: 2
Errors: 2
Harness.pl Run Time: 212 second(s).

The I think again, ok something must be wrong with this HTML library. So I go full on it and remove the HTML report and use just the console formatter:

# at t/mylongtest.t line 237.
t/mylongtest.t Run Time: 128 second(s).
# Looks like you failed 2 tests of 34.
Dubious, test returned 2 (wstat 512, 0x200)
Failed 2/34 subtests

Test Summary Report
-------------------
mylongtest (Wstat: 512 Tests: 34 Failed: 2)
Failed tests: 33-34
Non-zero exit status: 2
Files=1, Tests=34, 215 wallclock secs ( 0.22 usr + 0.12 sys = 0.34 CPU)
Result: FAIL
Passed: 32
Failed: 2
Errors: 2
Harness.pl Run Time: 216 second(s).

And then again I get this cray difference from 128 seconds from the end of the test to 216 seconds at the end of the harness.

The I tried to remove completly the harness script and just use prove and I get the same

So my question is. What is happening between the done_testing / end of a test and the reporting of the results of the the test harness and what can I do to improve this?

Update: I finally was able to reproduce the issue in a minimal example, and it seems that the problem is not TAP but what happens at the end of the script with a garbage collector or something similar. I create two scripts, first one delete_me.pl:

use strict;
use JSON;

my $huge_json_string = '{';

foreach my $i (0..20000000){
    $huge_json_string .= '"key_'.$i.'": "some_value'.$i.'",';
}
$huge_json_string =~ s/,$/}/;#
print "String generated\n";
my $all_to_ram = decode_json($huge_json_string);
print "Hash generated\n";

print( "$0 Run Time: " . ( time - $^T ) . " second(s).\n");

And now I call it from other script delete_me_caller.pl:

use strict;

system("perl delete_me.pl");
print( "$0 Run Time: " . ( time - $^T ) . " second(s).\n");

And here is the surprise:

String generated
Hash generated
delete_me.pl Run Time: 20 second(s).
delete_me_caller.pl Run Time: 42 second(s).

So it takes more time to end the script than to generate the data and load it to memory. Note: For this script I was using my personal computer with 32GB of ram and i7 8650 U so this may take a lot longer with less RAM or power.

0

There are 0 best solutions below