diff options
| -rwxr-xr-x | tests/runtests.pl | 82 |
1 files changed, 82 insertions, 0 deletions
diff --git a/tests/runtests.pl b/tests/runtests.pl index 33def4d91..57bf28ca5 100755 --- a/tests/runtests.pl +++ b/tests/runtests.pl @@ -58,6 +58,9 @@ BEGIN { @INC=(@INC, $ENV{'srcdir'}, "."); + if($] > 5.006) { + use Time::HiRes qw(time); + } } use strict; @@ -216,6 +219,11 @@ my $sshderror; # for socks server, ssh daemon version error my $defserverlogslocktimeout = 20; # timeout to await server logs lock removal my $defpostcommanddelay = 0; # delay between command and postcheck sections +my $timestats=1; # time stamping and stats generation +my %timetoolini; # timestamp for each test command run starting +my %timetoolend; # timestamp for each test command run stopping +my %timesrvrlog; # timestamp for each test server logs lock removal + my $testnumcheck; # test number, set in singletest sub. ####################################################################### @@ -248,6 +256,16 @@ sub logmsg { } } +# perl newer than 5.6 required for time stamping and stats generation +if(($] > 5.006) && $timestats) { + keys(%timetoolini) = 1000; + keys(%timetoolend) = 1000; + keys(%timesrvrlog) = 1000; +} +else { + $timestats = 0; +} + # get the name of the current user my $USER = $ENV{USER}; # Linux if (!$USER) { @@ -2118,6 +2136,10 @@ sub singletest { print GDBCMD "source $gdbinit\n" if -e $gdbinit; close(GDBCMD); } + + # timestamp starting of test command + $timetoolini{$testnum} = Time::HiRes::time() if($timestats); + # run the command line we built if ($torture) { $cmdres = torture($CMDLINE, @@ -2140,6 +2162,10 @@ sub singletest { $cmdres = (2000 + $signal_num) if($signal_num && !$cmdres); } } + + # timestamp finishing of test command + $timetoolend{$testnum} = Time::HiRes::time() if($timestats); + if(!$dumped_core) { if(-r "core") { # there's core file present now! @@ -2183,6 +2209,9 @@ sub singletest { sleep($postcommanddelay) if($postcommanddelay); + # timestamp removal of server logs advisor read lock + $timesrvrlog{$testnum} = Time::HiRes::time() if($timestats); + # run the postcheck command my @postcheck= getpart("client", "postcheck"); $cmd = $postcheck[0]; @@ -3202,6 +3231,59 @@ if($skipped) { } } +if($timestats) { + logmsg "\nGenerating execution time stats...\n\n"; + + my @timetool; + my @timelock; + my @timetest; + my $timetooltot = 0.0; + my $timelocktot = 0.0; + my $timetesttot = 0.0; + + for my $testnum (1 .. $lasttest) { + if($timetoolini{$testnum}) { + $timetooltot += $timetoolend{$testnum} - $timetoolini{$testnum}; + $timelocktot += $timesrvrlog{$testnum} - $timetoolend{$testnum}; + $timetesttot += $timesrvrlog{$testnum} - $timetoolini{$testnum}; + push @timetool, sprintf("%06.3f %04d", + $timetoolend{$testnum} - $timetoolini{$testnum}, $testnum); + push @timelock, sprintf("%06.3f %04d", + $timesrvrlog{$testnum} - $timetoolend{$testnum}, $testnum); + push @timetest, sprintf("%06.3f %04d", + $timesrvrlog{$testnum} - $timetoolini{$testnum}, $testnum); + } + } + @timetool = sort { $b <=> $a } @timetool; + @timelock = sort { $b <=> $a } @timelock; + @timetest = sort { $b <=> $a } @timetest; + + logmsg "Total tool time: ". sprintf("%07.2f", $timetooltot) ." seconds\n"; + logmsg "Total lock time: ". sprintf("%07.2f", $timelocktot) ." seconds\n"; + logmsg "Total test time: ". sprintf("%07.2f", $timetesttot) ." seconds\n"; + + logmsg "\nTool execution time per test...\n\n"; + logmsg "-time- test\n"; + logmsg "------ ----\n"; + foreach my $txt (@timetool) { + logmsg "$txt\n"; + } + + logmsg "\nServer logs lock removal time per test...\n\n"; + logmsg "-time- test\n"; + logmsg "------ ----\n"; + foreach my $txt (@timelock) { + logmsg "$txt\n"; + } + + logmsg "\nAggregated time per test...\n\n"; + logmsg "-time- test\n"; + logmsg "------ ----\n"; + foreach my $txt (@timetest) { + logmsg "$txt\n"; + } +} + if($total && ($ok != $total)) { exit 1; } |