diff options
| -rwxr-xr-x | tests/runtests.pl | 262 |
1 files changed, 136 insertions, 126 deletions
diff --git a/tests/runtests.pl b/tests/runtests.pl index e44241e31..f04a4c870 100755 --- a/tests/runtests.pl +++ b/tests/runtests.pl @@ -2876,6 +2876,138 @@ sub serverfortest { } ####################################################################### +# runtimestats displays test-suite run time statistics +# +sub runtimestats { + my $lasttest = $_[0]; + + return if(not $timestats); + + logmsg "\nTest suite total running time breakdown per task...\n\n"; + + my @timesrvr; + my @timeprep; + my @timetool; + my @timelock; + my @timevrfy; + my @timetest; + my $timesrvrtot = 0.0; + my $timepreptot = 0.0; + my $timetooltot = 0.0; + my $timelocktot = 0.0; + my $timevrfytot = 0.0; + my $timetesttot = 0.0; + my $counter; + + for my $testnum (1 .. $lasttest) { + if($timesrvrini{$testnum}) { + $timesrvrtot += $timesrvrend{$testnum} - $timesrvrini{$testnum}; + $timepreptot += + (($timetoolini{$testnum} - $timeprepini{$testnum}) - + ($timesrvrend{$testnum} - $timesrvrini{$testnum})); + $timetooltot += $timetoolend{$testnum} - $timetoolini{$testnum}; + $timelocktot += $timesrvrlog{$testnum} - $timetoolend{$testnum}; + $timevrfytot += $timevrfyend{$testnum} - $timesrvrlog{$testnum}; + $timetesttot += $timevrfyend{$testnum} - $timeprepini{$testnum}; + push @timesrvr, sprintf("%06.3f %04d", + $timesrvrend{$testnum} - $timesrvrini{$testnum}, $testnum); + push @timeprep, sprintf("%06.3f %04d", + ($timetoolini{$testnum} - $timeprepini{$testnum}) - + ($timesrvrend{$testnum} - $timesrvrini{$testnum}), $testnum); + push @timetool, sprintf("%06.3f %04d", + $timetoolend{$testnum} - $timetoolini{$testnum}, $testnum); + push @timelock, sprintf("%06.3f %04d", + $timesrvrlog{$testnum} - $timetoolend{$testnum}, $testnum); + push @timevrfy, sprintf("%06.3f %04d", + $timevrfyend{$testnum} - $timesrvrlog{$testnum}, $testnum); + push @timetest, sprintf("%06.3f %04d", + $timevrfyend{$testnum} - $timeprepini{$testnum}, $testnum); + } + } + @timesrvr = sort { $b <=> $a } @timesrvr; + @timeprep = sort { $b <=> $a } @timeprep; + @timetool = sort { $b <=> $a } @timetool; + @timelock = sort { $b <=> $a } @timelock; + @timevrfy = sort { $b <=> $a } @timevrfy; + @timetest = sort { $b <=> $a } @timetest; + + logmsg "Spent ". sprintf("%08.3f ", $timesrvrtot) . + "seconds starting and verifying test harness servers.\n"; + logmsg "Spent ". sprintf("%08.3f ", $timepreptot) . + "seconds reading definitions and doing test preparations.\n"; + logmsg "Spent ". sprintf("%08.3f ", $timetooltot) . + "seconds actually running test tools.\n"; + logmsg "Spent ". sprintf("%08.3f ", $timelocktot) . + "seconds awaiting server logs lock removal.\n"; + logmsg "Spent ". sprintf("%08.3f ", $timevrfytot) . + "seconds verifying test results.\n"; + logmsg "Spent ". sprintf("%08.3f ", $timetesttot) . + "seconds doing all of the above.\n"; + + $counter = 25; + logmsg "\nTest server starting and verification time per test ". + sprintf("(%s)...\n\n", (not $fullstats)?"top $counter":"full"); + logmsg "-time- test\n"; + logmsg "------ ----\n"; + foreach my $txt (@timesrvr) { + last if((not $fullstats) && (not $counter--)); + logmsg "$txt\n"; + } + + $counter = 10; + logmsg "\nTest definition reading and preparation time per test ". + sprintf("(%s)...\n\n", (not $fullstats)?"top $counter":"full"); + logmsg "-time- test\n"; + logmsg "------ ----\n"; + foreach my $txt (@timeprep) { + last if((not $fullstats) && (not $counter--)); + logmsg "$txt\n"; + } + + $counter = 25; + logmsg "\nTest tool execution time per test ". + sprintf("(%s)...\n\n", (not $fullstats)?"top $counter":"full"); + logmsg "-time- test\n"; + logmsg "------ ----\n"; + foreach my $txt (@timetool) { + last if((not $fullstats) && (not $counter--)); + logmsg "$txt\n"; + } + + $counter = 15; + logmsg "\nTest server logs lock removal time per test ". + sprintf("(%s)...\n\n", (not $fullstats)?"top $counter":"full"); + logmsg "-time- test\n"; + logmsg "------ ----\n"; + foreach my $txt (@timelock) { + last if((not $fullstats) && (not $counter--)); + logmsg "$txt\n"; + } + + $counter = 10; + logmsg "\nTest results verification time per test ". + sprintf("(%s)...\n\n", (not $fullstats)?"top $counter":"full"); + logmsg "-time- test\n"; + logmsg "------ ----\n"; + foreach my $txt (@timevrfy) { + last if((not $fullstats) && (not $counter--)); + logmsg "$txt\n"; + } + + $counter = 50; + logmsg "\nTotal time per test ". + sprintf("(%s)...\n\n", (not $fullstats)?"top $counter":"full"); + logmsg "-time- test\n"; + logmsg "------ ----\n"; + foreach my $txt (@timetest) { + last if((not $fullstats) && (not $counter--)); + logmsg "$txt\n"; + } + + logmsg "\n"; +} + +####################################################################### # Check options to this test program # @@ -3295,6 +3427,8 @@ foreach $testnum (@at) { # loop for next test } +my $sofar = time() - $start; + ####################################################################### # Close command log # @@ -3307,6 +3441,8 @@ unlink($SOCKSPIDFILE); my $all = $total + $skipped; +runtimestats($lasttest); + if($total) { logmsg sprintf("TESTDONE: $ok tests out of $total reported OK: %d%%\n", $ok/$total*100); @@ -3320,7 +3456,6 @@ else { } if($all) { - my $sofar = time()-$start; logmsg "TESTDONE: $all tests were considered during ". sprintf("%.0f", $sofar) ." seconds.\n"; } @@ -3348,131 +3483,6 @@ if($skipped) { } } -if($timestats) { - logmsg "\nTest suite total running time breakdown per task...\n\n"; - - my @timesrvr; - my @timeprep; - my @timetool; - my @timelock; - my @timevrfy; - my @timetest; - my $timesrvrtot = 0.0; - my $timepreptot = 0.0; - my $timetooltot = 0.0; - my $timelocktot = 0.0; - my $timevrfytot = 0.0; - my $timetesttot = 0.0; - my $counter; - - for my $testnum (1 .. $lasttest) { - if($timesrvrini{$testnum}) { - $timesrvrtot += $timesrvrend{$testnum} - $timesrvrini{$testnum}; - $timepreptot += - (($timetoolini{$testnum} - $timeprepini{$testnum}) - - ($timesrvrend{$testnum} - $timesrvrini{$testnum})); - $timetooltot += $timetoolend{$testnum} - $timetoolini{$testnum}; - $timelocktot += $timesrvrlog{$testnum} - $timetoolend{$testnum}; - $timevrfytot += $timevrfyend{$testnum} - $timesrvrlog{$testnum}; - $timetesttot += $timevrfyend{$testnum} - $timeprepini{$testnum}; - push @timesrvr, sprintf("%06.3f %04d", - $timesrvrend{$testnum} - $timesrvrini{$testnum}, $testnum); - push @timeprep, sprintf("%06.3f %04d", - ($timetoolini{$testnum} - $timeprepini{$testnum}) - - ($timesrvrend{$testnum} - $timesrvrini{$testnum}), $testnum); - push @timetool, sprintf("%06.3f %04d", - $timetoolend{$testnum} - $timetoolini{$testnum}, $testnum); - push @timelock, sprintf("%06.3f %04d", - $timesrvrlog{$testnum} - $timetoolend{$testnum}, $testnum); - push @timevrfy, sprintf("%06.3f %04d", - $timevrfyend{$testnum} - $timesrvrlog{$testnum}, $testnum); - push @timetest, sprintf("%06.3f %04d", - $timevrfyend{$testnum} - $timeprepini{$testnum}, $testnum); - } - } - @timesrvr = sort { $b <=> $a } @timesrvr; - @timeprep = sort { $b <=> $a } @timeprep; - @timetool = sort { $b <=> $a } @timetool; - @timelock = sort { $b <=> $a } @timelock; - @timevrfy = sort { $b <=> $a } @timevrfy; - @timetest = sort { $b <=> $a } @timetest; - - logmsg "Spent ". sprintf("%08.3f ", $timesrvrtot) . - "seconds starting and verifying test harness servers.\n"; - logmsg "Spent ". sprintf("%08.3f ", $timepreptot) . - "seconds reading definitions and doing test preparations.\n"; - logmsg "Spent ". sprintf("%08.3f ", $timetooltot) . - "seconds actually running test tools.\n"; - logmsg "Spent ". sprintf("%08.3f ", $timelocktot) . - "seconds awaiting server logs lock removal.\n"; - logmsg "Spent ". sprintf("%08.3f ", $timevrfytot) . - "seconds verifying test results.\n"; - logmsg "Spent ". sprintf("%08.3f ", $timetesttot) . - "seconds doing all of the above.\n"; - - $counter = 25; - logmsg "\nTest server starting and verification time per test ". - sprintf("(%s)...\n\n", (not $fullstats)?"top $counter":"full"); - logmsg "-time- test\n"; - logmsg "------ ----\n"; - foreach my $txt (@timesrvr) { - last if((not $fullstats) && (not $counter--)); - logmsg "$txt\n"; - } - - $counter = 10; - logmsg "\nTest definition reading and preparation time per test ". - sprintf("(%s)...\n\n", (not $fullstats)?"top $counter":"full"); - logmsg "-time- test\n"; - logmsg "------ ----\n"; - foreach my $txt (@timeprep) { - last if((not $fullstats) && (not $counter--)); - logmsg "$txt\n"; - } - - $counter = 25; - logmsg "\nTest tool execution time per test ". - sprintf("(%s)...\n\n", (not $fullstats)?"top $counter":"full"); - logmsg "-time- test\n"; - logmsg "------ ----\n"; - foreach my $txt (@timetool) { - last if((not $fullstats) && (not $counter--)); - logmsg "$txt\n"; - } - - $counter = 15; - logmsg "\nTest server logs lock removal time per test ". - sprintf("(%s)...\n\n", (not $fullstats)?"top $counter":"full"); - logmsg "-time- test\n"; - logmsg "------ ----\n"; - foreach my $txt (@timelock) { - last if((not $fullstats) && (not $counter--)); - logmsg "$txt\n"; - } - - $counter = 10; - logmsg "\nTest results verification time per test ". - sprintf("(%s)...\n\n", (not $fullstats)?"top $counter":"full"); - logmsg "-time- test\n"; - logmsg "------ ----\n"; - foreach my $txt (@timevrfy) { - last if((not $fullstats) && (not $counter--)); - logmsg "$txt\n"; - } - - $counter = 50; - logmsg "\nTotal time per test ". - sprintf("(%s)...\n\n", (not $fullstats)?"top $counter":"full"); - logmsg "-time- test\n"; - logmsg "------ ----\n"; - foreach my $txt (@timetest) { - last if((not $fullstats) && (not $counter--)); - logmsg "$txt\n"; - } - - logmsg "\n"; -} - if($total && ($ok != $total)) { exit 1; } |