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:
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 subtestsTest 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.