Make 'classic' output end of a test-suite run become again the end

of output, even when run time statistics are shown.

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;
 }