aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
-rwxr-xr-xtests/runtests.pl82
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;
}