aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
-rwxr-xr-xtests/runtests.pl107
1 files changed, 99 insertions, 8 deletions
diff --git a/tests/runtests.pl b/tests/runtests.pl
index 57bf28ca5..f234a7ff9 100755
--- a/tests/runtests.pl
+++ b/tests/runtests.pl
@@ -220,6 +220,9 @@ 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 %timeprepini; # timestamp for each test preparation start
+my %timesrvrini; # timestamp for each test required servers verification start
+my %timesrvrend; # timestamp for each test required servers verification end
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
@@ -258,6 +261,9 @@ sub logmsg {
# perl newer than 5.6 required for time stamping and stats generation
if(($] > 5.006) && $timestats) {
+ keys(%timeprepini) = 1000;
+ keys(%timesrvrini) = 1000;
+ keys(%timesrvrend) = 1000;
keys(%timetoolini) = 1000;
keys(%timetoolend) = 1000;
keys(%timesrvrlog) = 1000;
@@ -1762,9 +1768,48 @@ sub fixarray {
}
#######################################################################
-# Run a single specified test case
+# Provide time stamps for single test skipped events
#
+sub timestampskippedevents {
+ my $testnum = $_[0];
+
+ return if((not defined($testnum)) || ($testnum < 1));
+
+ if($timestats) {
+ if($timesrvrlog{$testnum}) {
+ return;
+ }
+ elsif($timetoolend{$testnum}) {
+ $timesrvrlog{$testnum} = $timetoolend{$testnum};
+ }
+ elsif($timetoolini{$testnum}) {
+ $timesrvrlog{$testnum} = $timetoolini{$testnum};
+ $timetoolend{$testnum} = $timetoolini{$testnum};
+ }
+ elsif($timesrvrend{$testnum}) {
+ $timesrvrlog{$testnum} = $timesrvrend{$testnum};
+ $timetoolend{$testnum} = $timesrvrend{$testnum};
+ $timetoolini{$testnum} = $timesrvrend{$testnum};
+ }
+ elsif($timesrvrini{$testnum}) {
+ $timesrvrlog{$testnum} = $timesrvrini{$testnum};
+ $timetoolend{$testnum} = $timesrvrini{$testnum};
+ $timetoolini{$testnum} = $timesrvrini{$testnum};
+ $timesrvrend{$testnum} = $timesrvrini{$testnum};
+ }
+ elsif($timeprepini{$testnum}) {
+ $timesrvrlog{$testnum} = $timeprepini{$testnum};
+ $timetoolend{$testnum} = $timeprepini{$testnum};
+ $timetoolini{$testnum} = $timeprepini{$testnum};
+ $timesrvrend{$testnum} = $timeprepini{$testnum};
+ $timesrvrini{$testnum} = $timeprepini{$testnum};
+ }
+ }
+}
+#######################################################################
+# Run a single specified test case
+#
sub singletest {
my ($testnum, $count, $total)=@_;
@@ -1777,6 +1822,9 @@ sub singletest {
# testnum checking when starting test harness servers.
$testnumcheck = $testnum;
+ # timestamp test preparation start
+ $timeprepini{$testnum} = Time::HiRes::time() if($timestats);
+
# load the test case file definition
if(loadtest("${TESTDIR}/test${testnum}")) {
if($verbose) {
@@ -1885,10 +1933,16 @@ sub singletest {
}
}
+ # timestamp required servers verification start
+ $timesrvrini{$testnum} = Time::HiRes::time() if($timestats);
+
if(!$why) {
$why = serverfortest($testnum);
}
+ # timestamp required servers verification end
+ $timesrvrend{$testnum} = Time::HiRes::time() if($timestats);
+
if(!$why) {
my @precheck = getpart("client", "precheck");
$cmd = $precheck[0];
@@ -1916,6 +1970,7 @@ sub singletest {
printf "test %03d SKIPPED: $why\n", $testnum;
}
+ timestampskippedevents($testnum);
return -1;
}
logmsg sprintf("test %03d...", $testnum);
@@ -1968,6 +2023,7 @@ sub singletest {
}
if($listonly) {
+ timestampskippedevents($testnum);
return 0; # look successful
}
@@ -2026,6 +2082,7 @@ sub singletest {
if(@inputfile || $filename) {
if(!$filename) {
logmsg "ERROR: section client=>file has no name attribute\n";
+ timestampskippedevents($testnum);
return -1;
}
my $fileContent = join('', @inputfile);
@@ -2091,6 +2148,7 @@ sub singletest {
$CMDLINE="$LIBDIR/$tool";
if(! -f $CMDLINE) {
print "The tool set in the test case for this: '$tool' does not exist\n";
+ timestampskippedevents($testnum);
return -1;
}
$DBGCURL=$CMDLINE;
@@ -2124,6 +2182,7 @@ sub singletest {
logmsg "perl: $code\n";
logmsg "precommand: $@";
stopservers($verbose);
+ timestampskippedevents($testnum);
return -1;
}
}
@@ -3205,7 +3264,8 @@ else {
if($all) {
my $sofar = time()-$start;
- logmsg "TESTDONE: $all tests were considered during $sofar seconds.\n";
+ logmsg "TESTDONE: $all tests were considered during ".
+ sprintf("%.0f", $sofar) ." seconds.\n";
}
if($skipped) {
@@ -3234,33 +3294,64 @@ if($skipped) {
if($timestats) {
logmsg "\nGenerating execution time stats...\n\n";
+ my @timesrvr;
+ my @timeprep;
my @timetool;
my @timelock;
my @timetest;
+ my $timesrvrtot = 0.0;
+ my $timepreptot = 0.0;
my $timetooltot = 0.0;
my $timelocktot = 0.0;
my $timetesttot = 0.0;
for my $testnum (1 .. $lasttest) {
- if($timetoolini{$testnum}) {
+ 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};
- $timetesttot += $timesrvrlog{$testnum} - $timetoolini{$testnum};
+ $timetesttot += $timesrvrlog{$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 @timetest, sprintf("%06.3f %04d",
- $timesrvrlog{$testnum} - $timetoolini{$testnum}, $testnum);
+ $timesrvrlog{$testnum} - $timeprepini{$testnum}, $testnum);
}
}
+ @timesrvr = sort { $b <=> $a } @timesrvr;
+ @timeprep = sort { $b <=> $a } @timeprep;
@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 "Total srvr time: ". sprintf("%08.3f", $timesrvrtot) ." seconds\n";
+ logmsg "Total prep time: ". sprintf("%08.3f", $timepreptot) ." seconds\n";
+ logmsg "Total tool time: ". sprintf("%08.3f", $timetooltot) ." seconds\n";
+ logmsg "Total lock time: ". sprintf("%08.3f", $timelocktot) ." seconds\n";
+ logmsg "Total test time: ". sprintf("%08.3f", $timetesttot) ." seconds\n";
+
+ logmsg "\nServer start verification time per test...\n\n";
+ logmsg "-time- test\n";
+ logmsg "------ ----\n";
+ foreach my $txt (@timesrvr) {
+ logmsg "$txt\n";
+ }
+
+ logmsg "\nTest preparation time per test...\n\n";
+ logmsg "-time- test\n";
+ logmsg "------ ----\n";
+ foreach my $txt (@timeprep) {
+ logmsg "$txt\n";
+ }
logmsg "\nTool execution time per test...\n\n";
logmsg "-time- test\n";