From aeec8e0b38f43121e8b921637e4a4af50bde7a0c Mon Sep 17 00:00:00 2001 From: Yang Tse Date: Sat, 19 Dec 2009 04:15:22 +0000 Subject: [PATCH] Added runtests.pl '-r' option for run time statistics --- tests/Makefile.am | 2 +- tests/runtests.pl | 167 +++++++++++++++++++++++++++++++++++++++++++----------- 2 files changed, 134 insertions(+), 35 deletions(-) diff --git a/tests/Makefile.am b/tests/Makefile.am index 32f27b5..35525f7 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -48,7 +48,7 @@ TEST_T = else # if not cross-compiling: TEST = srcdir=$(srcdir) $(PERL) $(PERLFLAGS) $(srcdir)/runtests.pl TEST_Q = -a -s -TEST_F = -a -p +TEST_F = -a -p -r TEST_T = -a -t endif diff --git a/tests/runtests.pl b/tests/runtests.pl index f234a7f..39a5531 100755 --- a/tests/runtests.pl +++ b/tests/runtests.pl @@ -58,8 +58,9 @@ BEGIN { @INC=(@INC, $ENV{'srcdir'}, "."); - if($] > 5.006) { - use Time::HiRes qw(time); + # run time statistics needs perl 5.7 or newer + if($] >= 5.007) { + use Time::HiRes qw( time ); } } @@ -219,13 +220,15 @@ 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 $timestats; # time stamping and stats generation +my $fullstats; # show time stats for every single test 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 +my %timevrfyend; # timestamp for each test result verification end my $testnumcheck; # test number, set in singletest sub. @@ -259,19 +262,6 @@ 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; -} -else { - $timestats = 0; -} - # get the name of the current user my $USER = $ENV{USER}; # Linux if (!$USER) { @@ -1776,28 +1766,38 @@ sub timestampskippedevents { return if((not defined($testnum)) || ($testnum < 1)); if($timestats) { - if($timesrvrlog{$testnum}) { + + if($timevrfyend{$testnum}) { + return; + } + elsif($timesrvrlog{$testnum}) { + $timevrfyend{$testnum} = $timesrvrlog{$testnum}; return; } elsif($timetoolend{$testnum}) { + $timevrfyend{$testnum} = $timetoolend{$testnum}; $timesrvrlog{$testnum} = $timetoolend{$testnum}; } elsif($timetoolini{$testnum}) { + $timevrfyend{$testnum} = $timetoolini{$testnum}; $timesrvrlog{$testnum} = $timetoolini{$testnum}; $timetoolend{$testnum} = $timetoolini{$testnum}; } elsif($timesrvrend{$testnum}) { + $timevrfyend{$testnum} = $timesrvrend{$testnum}; $timesrvrlog{$testnum} = $timesrvrend{$testnum}; $timetoolend{$testnum} = $timesrvrend{$testnum}; $timetoolini{$testnum} = $timesrvrend{$testnum}; } elsif($timesrvrini{$testnum}) { + $timevrfyend{$testnum} = $timesrvrini{$testnum}; $timesrvrlog{$testnum} = $timesrvrini{$testnum}; $timetoolend{$testnum} = $timesrvrini{$testnum}; $timetoolini{$testnum} = $timesrvrini{$testnum}; $timesrvrend{$testnum} = $timesrvrini{$testnum}; } elsif($timeprepini{$testnum}) { + $timevrfyend{$testnum} = $timeprepini{$testnum}; $timesrvrlog{$testnum} = $timeprepini{$testnum}; $timetoolend{$testnum} = $timeprepini{$testnum}; $timetoolini{$testnum} = $timeprepini{$testnum}; @@ -2251,9 +2251,9 @@ sub singletest { # of time until the server removes it, or the given time expires. if($serverlogslocktimeout) { - my $lockretry = $serverlogslocktimeout * 4; + my $lockretry = $serverlogslocktimeout * 8; while((-f $SERVERLOGS_LOCK) && $lockretry--) { - select(undef, undef, undef, 0.25); + select(undef, undef, undef, 0.125); } if(($lockretry < 0) && ($serverlogslocktimeout >= $defserverlogslocktimeout)) { @@ -2283,6 +2283,8 @@ sub singletest { # to clean up, but the result can't be relied upon. if($rc != 0 && !$torture) { logmsg " postcheck FAILED\n"; + # timestamp test result verification end + $timevrfyend{$testnum} = Time::HiRes::time() if($timestats); return 1; } } @@ -2300,6 +2302,8 @@ sub singletest { if(!$cmdres && !$keepoutfiles) { cleardir($LOGDIR); } + # timestamp test result verification end + $timevrfyend{$testnum} = Time::HiRes::time() if($timestats); return $cmdres; } @@ -2332,6 +2336,8 @@ sub singletest { $res = compare("stdout", \@actual, \@validstdout); if($res) { + # timestamp test result verification end + $timevrfyend{$testnum} = Time::HiRes::time() if($timestats); return 1; } $ok .= "s"; @@ -2354,6 +2360,8 @@ sub singletest { $res = compare("data", \@out, \@reply); if ($res) { + # timestamp test result verification end + $timevrfyend{$testnum} = Time::HiRes::time() if($timestats); return 1; } $ok .= "d"; @@ -2367,6 +2375,8 @@ sub singletest { my @out = loadarray("$LOGDIR/upload.$testnum"); $res = compare("upload", \@out, \@upload); if ($res) { + # timestamp test result verification end + $timevrfyend{$testnum} = Time::HiRes::time() if($timestats); return 1; } $ok .= "u"; @@ -2412,6 +2422,8 @@ sub singletest { $res = compare("protocol", \@out, \@protstrip); if($res) { + # timestamp test result verification end + $timevrfyend{$testnum} = Time::HiRes::time() if($timestats); return 1; } @@ -2431,6 +2443,8 @@ sub singletest { if(!$filename) { logmsg "ERROR: section verify=>file has no name attribute\n"; stopservers($verbose); + # timestamp test result verification end + $timevrfyend{$testnum} = Time::HiRes::time() if($timestats); return -1; } my @generated=loadarray($filename); @@ -2457,6 +2471,8 @@ sub singletest { $res = compare("output", \@generated, \@outfile); if($res) { + # timestamp test result verification end + $timevrfyend{$testnum} = Time::HiRes::time() if($timestats); return 1; } @@ -2486,6 +2502,8 @@ sub singletest { (!$tool)?"curl":$tool, $errorcode); } logmsg " exit FAILED\n"; + # timestamp test result verification end + $timevrfyend{$testnum} = Time::HiRes::time() if($timestats); return 1; } @@ -2524,6 +2542,8 @@ sub singletest { if($leak) { logmsg "\n** MEMORY FAILURE\n"; logmsg @memdata; + # timestamp test result verification end + $timevrfyend{$testnum} = Time::HiRes::time() if($timestats); return 1; } else { @@ -2539,8 +2559,11 @@ sub singletest { # this is the valid protocol blurb curl should generate if($usevalgrind) { - opendir(DIR, "log") || + if(!opendir(DIR, "log")) { + # timestamp test result verification end + $timevrfyend{$testnum} = Time::HiRes::time() if($timestats); return 0; # can't open log dir + } my @files = readdir(DIR); closedir(DIR); my $f; @@ -2559,6 +2582,8 @@ sub singletest { if($e[0]) { logmsg " valgrind ERROR "; logmsg @e; + # timestamp test result verification end + $timevrfyend{$testnum} = Time::HiRes::time() if($timestats); return 1; } $ok .= "v"; @@ -2591,6 +2616,9 @@ sub singletest { unlink($FTPDCMD); # remove the instructions for this test + # timestamp test result verification end + $timevrfyend{$testnum} = Time::HiRes::time() if($timestats); + return 0; } @@ -2920,6 +2948,34 @@ while(@ARGV) { # keep stdout and stderr files after tests $keepoutfiles=1; } + elsif($ARGV[0] eq "-r") { + # run time statistics needs perl 5.7 or newer + if($] >= 5.007) { + keys(%timeprepini) = 1000; + keys(%timesrvrini) = 1000; + keys(%timesrvrend) = 1000; + keys(%timetoolini) = 1000; + keys(%timetoolend) = 1000; + keys(%timesrvrlog) = 1000; + keys(%timevrfyend) = 1000; + $timestats=1; + $fullstats=0; + } + } + elsif($ARGV[0] eq "-rf") { + # run time statistics needs perl 5.7 or newer + if($] >= 5.007) { + keys(%timeprepini) = 1000; + keys(%timesrvrini) = 1000; + keys(%timesrvrend) = 1000; + keys(%timetoolini) = 1000; + keys(%timetoolend) = 1000; + keys(%timesrvrlog) = 1000; + keys(%timevrfyend) = 1000; + $timestats=1; + $fullstats=1; + } + } elsif(($ARGV[0] eq "-h") || ($ARGV[0] eq "--help")) { # show help text print < $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 "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 "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"; } - logmsg "\nTest preparation time per test...\n\n"; + $counter = 25; + 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"; } - logmsg "\nTool execution time per test...\n\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"; } - logmsg "\nServer logs lock removal time per test...\n\n"; + $counter = 25; + 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"; } - logmsg "\nAggregated time per test...\n\n"; + $counter = 25; + 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 "\nAggregated 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)) { -- 2.7.4