#At file:///home/bm136801/my/mtr-tr/ based on revid:bjorn.munch@stripped
2975 Bjorn Munch 2010-10-19 [merge]
upmerge 40406,55135,55968,56654
modified:
mysql-test/lib/mtr_misc.pl
mysql-test/lib/mtr_process.pl
mysql-test/mysql-test-run.pl
mysql-test/t/mysqltest.test
mysql-test/t/wait_timeout.test
=== modified file 'mysql-test/lib/mtr_misc.pl'
--- a/mysql-test/lib/mtr_misc.pl 2010-06-07 09:14:56 +0000
+++ b/mysql-test/lib/mtr_misc.pl 2010-10-19 13:05:25 +0000
@@ -33,6 +33,13 @@ sub mtr_exe_maybe_exists(@);
sub mtr_milli_sleep($);
sub start_timer($);
sub has_expired($);
+sub init_timers();
+sub mark_time_used($);
+sub add_total_times($);
+sub print_times_used($$);
+sub print_total_times($);
+
+our $opt_report_times;
##############################################################################
#
@@ -205,4 +212,81 @@ sub start_timer ($) { return time + $_[0
sub has_expired ($) { return $_[0] && time gt $_[0]; }
+# Below code is for time usage reporting
+
+use Time::HiRes qw(gettimeofday);
+
+my %time_used= (
+ 'collect' => 0,
+ 'restart' => 0,
+ 'check' => 0,
+ 'ch-warn' => 0,
+ 'test' => 0,
+ 'init' => 0,
+);
+
+my %time_text= (
+ 'collect' => "Collecting test cases",
+ 'restart' => "Server stop/start",
+ 'check' => "Check-testcase",
+ 'ch-warn' => "Check for warnings",
+ 'test' => "Test execution",
+ 'init' => "Initialization etc.",
+);
+
+# Counts number of reports from workers
+
+my $time_totals= 0;
+
+my $last_timer_set;
+
+sub init_timers() {
+ $last_timer_set= gettimeofday();
+}
+
+sub mark_time_used($) {
+ my ($name)= @_;
+ return unless $opt_report_times;
+ die "Unknown timer $name" unless exists $time_used{$name};
+
+ my $curr_time= gettimeofday();
+ $time_used{$name}+= int (($curr_time - $last_timer_set) * 1000 + .5);
+ $last_timer_set= $curr_time;
+}
+
+sub add_total_times($) {
+ my ($dummy, $num, @line)= split (" ", $_[0]);
+
+ $time_totals++;
+ foreach my $elem (@line) {
+ my ($name, $spent)= split (":", $elem);
+ $time_used{$name}+= $spent;
+ }
+}
+
+sub print_times_used($$) {
+ my ($server, $num)= @_;
+ return unless $opt_report_times;
+
+ my $output= "SPENT $num";
+ foreach my $name (keys %time_used) {
+ my $spent= $time_used{$name};
+ $output.= " $name:$spent";
+ }
+ print $server $output . "\n";
+}
+
+sub print_total_times($) {
+ # Don't print if we haven't received all worker data
+ return if $time_totals != $_[0];
+
+ foreach my $name (keys %time_used)
+ {
+ my $spent= $time_used{$name}/1000;
+ my $text= $time_text{$name};
+ print ("Spent $spent seconds on $text\n");
+ }
+}
+
+
1;
=== modified file 'mysql-test/lib/mtr_process.pl'
--- a/mysql-test/lib/mtr_process.pl 2010-06-14 09:31:22 +0000
+++ b/mysql-test/lib/mtr_process.pl 2010-10-12 11:13:23 +0000
@@ -116,18 +116,20 @@ sub sleep_until_file_created ($$$) {
return 1;
}
+ my $seconds= ($loop * $sleeptime) / 1000;
+
# Check if it died after the fork() was successful
if ( defined $proc and ! $proc->wait_one(0) )
{
- mtr_warning("Process $proc died");
+ mtr_warning("Process $proc died after mysql-test-run waited $seconds " .
+ "seconds for $pidfile to be created.");
return 0;
}
mtr_debug("Sleep $sleeptime milliseconds waiting for $pidfile");
# Print extra message every 60 seconds
- my $seconds= ($loop * $sleeptime) / 1000;
- if ( $seconds > 1 and int($seconds * 10) % 600 == 0 )
+ if ( $seconds > 1 && int($seconds * 10) % 600 == 0 && $seconds < $timeout )
{
my $left= $timeout - $seconds;
mtr_warning("Waited $seconds seconds for $pidfile to be created, " .
@@ -138,6 +140,8 @@ sub sleep_until_file_created ($$$) {
}
+ mtr_warning("Timeout after mysql-test-run waited $timeout seconds " .
+ "for the process $proc to create a pid file.");
return 0;
}
=== modified file 'mysql-test/mysql-test-run.pl'
--- a/mysql-test/mysql-test-run.pl 2010-09-30 10:55:39 +0000
+++ b/mysql-test/mysql-test-run.pl 2010-10-19 13:05:25 +0000
@@ -195,6 +195,7 @@ sub using_extern { return (keys %opts_ex
our $opt_fast= 0;
our $opt_force;
our $opt_mem= $ENV{'MTR_MEM'};
+our $opt_clean_vardir= $ENV{'MTR_CLEAN_VARDIR'};
our $opt_gcov;
our $opt_gcov_exe= "gcov";
@@ -235,6 +236,7 @@ my $opt_skip_core;
our $opt_check_testcases= 1;
my $opt_mark_progress;
my $opt_max_connections;
+our $opt_report_times= 0;
my $opt_sleep;
@@ -347,8 +349,11 @@ sub main {
}
}
+ init_timers();
+
mtr_report("Collecting tests...");
my $tests= collect_test_cases($opt_reorder, $opt_suites, \@opt_cases, \@opt_skip_test_list);
+ mark_time_used('collect');
if ( $opt_report_features ) {
# Put "report features" as the first test to run
@@ -417,6 +422,7 @@ sub main {
$opt_tmpdir= "$opt_tmpdir/$child_num";
}
+ init_timers();
run_worker($server_port, $child_num);
exit(1);
}
@@ -429,6 +435,8 @@ sub main {
mtr_print_thick_line();
mtr_print_header();
+ mark_time_used('init');
+
my $completed= run_test_server($server, $tests, $opt_parallel);
exit(0) if $opt_start_exit;
@@ -474,8 +482,12 @@ sub main {
$opt_gcov_msg, $opt_gcov_err);
}
+ print_total_times($opt_parallel) if $opt_report_times;
+
mtr_report_stats("Completed", $completed);
+ remove_vardir_subs() if $opt_clean_vardir;
+
exit(0);
}
@@ -606,13 +618,15 @@ sub run_test_server ($$$) {
if ($test_has_failed and $retries <= $opt_retry){
# Test should be run one more time unless it has failed
# too many times already
+ my $tname= $result->{name};
my $failures= $result->{failures};
if ($opt_retry > 1 and $failures >= $opt_retry_failure){
- mtr_report("\nTest has failed $failures times,",
+ mtr_report("\nTest $tname has failed $failures times,",
"no more retries!\n");
}
else {
- mtr_report("\nRetrying test, attempt($retries/$opt_retry)...\n");
+ mtr_report("\nRetrying test $tname, ".
+ "attempt($retries/$opt_retry)...\n");
delete($result->{result});
$result->{retries}= $retries+1;
$result->write_test($sock, 'TESTCASE');
@@ -648,6 +662,9 @@ sub run_test_server ($$$) {
elsif ($line eq 'START'){
; # Send first test
}
+ elsif ($line =~ /^SPENT/) {
+ add_total_times($line);
+ }
else {
mtr_error("Unknown response: '$line' from client");
}
@@ -779,7 +796,9 @@ sub run_worker ($) {
# Ask server for first test
print $server "START\n";
- while(my $line= <$server>){
+ mark_time_used('init');
+
+ while (my $line= <$server>){
chomp($line);
if ($line eq 'TESTCASE'){
my $test= My::Test::read_test($server);
@@ -797,16 +816,20 @@ sub run_worker ($) {
# Send it back, now with results set
#$test->print_test();
$test->write_test($server, 'TESTRESULT');
+ mark_time_used('restart');
}
elsif ($line eq 'BYE'){
mtr_report("Server said BYE");
stop_all_servers($opt_shutdown_timeout);
+ mark_time_used('restart');
if ($opt_valgrind_mysqld) {
valgrind_exit_reports();
}
if ( $opt_gprof ) {
gprof_collect (find_mysqld($basedir), keys %gprof_dirs);
}
+ mark_time_used('init');
+ print_times_used($server, $thread_num);
exit(0);
}
else {
@@ -946,6 +969,7 @@ sub command_line_setup {
'tmpdir=s' => \$opt_tmpdir,
'vardir=s' => \$opt_vardir,
'mem' => \$opt_mem,
+ 'clean-vardir' => \$opt_clean_vardir,
'client-bindir=s' => \$path_client_bindir,
'client-libdir=s' => \$path_client_libdir,
@@ -978,6 +1002,7 @@ sub command_line_setup {
'timediff' => \&report_option,
'max-connections=i' => \$opt_max_connections,
'default-myisam!' => \&collect_option,
+ 'report-times' => \$opt_report_times,
'help|h' => \$opt_usage,
'list-options' => \$opt_list_options,
@@ -2202,6 +2227,12 @@ sub environment_setup {
}
+sub remove_vardir_subs() {
+ foreach my $sdir ( glob("$opt_vardir/*") ) {
+ mtr_verbose("Removing subdir $sdir");
+ rmtree($sdir);
+ }
+}
#
# Remove var and any directories in var/ created by previous
@@ -2246,11 +2277,7 @@ sub remove_stale_vardir () {
mtr_error("The destination for symlink $opt_vardir does not exist")
if ! -d readlink($opt_vardir);
- foreach my $bin ( glob("$opt_vardir/*") )
- {
- mtr_verbose("Removing bin $bin");
- rmtree($bin);
- }
+ remove_vardir_subs();
}
}
else
@@ -3163,6 +3190,7 @@ sub check_testcase($$)
if ( keys(%started) == 0){
# All checks completed
+ mark_time_used('check');
return 0;
}
# Wait for next process to exit
@@ -3178,7 +3206,8 @@ sub check_testcase($$)
"\nMTR's internal check of the test case '$tname' failed.
This means that the test case does not preserve the state that existed
before the test case was executed. Most likely the test case did not
-do a proper clean-up.
+do a proper clean-up. It could also be caused by the previous test run
+by this thread, if the server wasn't restarted.
This is the diff of the states of the servers before and after the
test case was executed:\n";
$tinfo->{check}.= $report;
@@ -3220,6 +3249,11 @@ test case was executed:\n";
# Kill any check processes still running
map($_->kill(), values(%started));
+ mtr_warning("Check-testcase failed, this could also be caused by the" .
+ " previous test run by this worker thread")
+ if $result > 1 && $mode eq "before";
+ mark_time_used('check');
+
return $result;
}
@@ -3529,6 +3563,7 @@ sub run_testcase ($) {
return 1;
}
}
+ mark_time_used('restart');
# --------------------------------------------------------------------
# If --start or --start-dirty given, stop here to let user manually
@@ -3581,6 +3616,8 @@ sub run_testcase ($) {
do_before_run_mysqltest($tinfo);
+ mark_time_used('init');
+
if ( $opt_check_testcases and check_testcase($tinfo, "before") ){
# Failed to record state of server or server crashed
report_failure_and_restart($tinfo);
@@ -3627,6 +3664,7 @@ sub run_testcase ($) {
}
mtr_verbose("Got $proc");
+ mark_time_used('test');
# ----------------------------------------------------
# Was it the test program that exited
# ----------------------------------------------------
@@ -3853,7 +3891,9 @@ sub get_log_from_proc ($$) {
foreach my $mysqld (mysqlds()) {
if ($mysqld->{proc} eq $proc) {
my @srv_lines= extract_server_log($mysqld->value('#log-error'), $name);
- $srv_log= "\nServer log from this test:\n" . join ("", @srv_lines);
+ $srv_log= "\nServer log from this test:\n" .
+ "----------SERVER LOG START-----------\n". join ("", @srv_lines) .
+ "----------SERVER LOG END-------------\n";
last;
}
}
@@ -4030,6 +4070,7 @@ sub check_warnings ($) {
if ( keys(%started) == 0){
# All checks completed
+ mark_time_used('ch-warn');
return $result;
}
# Wait for next process to exit
@@ -4062,6 +4103,7 @@ sub check_warnings ($) {
# Kill any check processes still running
map($_->kill(), values(%started));
+ mark_time_used('ch-warn');
return $result;
}
@@ -5031,6 +5073,8 @@ sub start_mysqltest ($) {
my $exe= $exe_mysqltest;
my $args;
+ mark_time_used('init');
+
mtr_init_args(\$args);
mtr_add_arg($args, "--defaults-file=%s", $path_config_file);
@@ -5508,6 +5552,8 @@ Options to control directories to use
for tmpfs (/dev/shm)
The option can also be set using environment
variable MTR_MEM=[DIR]
+ clean-vardir Clean vardir if tests were successful and if
+ running in "memory". Otherwise this option is ignored
client-bindir=PATH Path to the directory where client binaries are located
client-libdir=PATH Path to the directory where client libraries are located
@@ -5666,6 +5712,8 @@ Misc options
default-myisam Set default storage engine to MyISAM for non-innodb
tests. This is needed after switching default storage
engine to InnoDB.
+ report-times Report how much time has been spent on different
+ phases of test execution.
HERE
exit(1);
=== modified file 'mysql-test/t/mysqltest.test'
--- a/mysql-test/t/mysqltest.test 2010-09-28 14:01:36 +0000
+++ b/mysql-test/t/mysqltest.test 2010-10-19 13:05:25 +0000
@@ -331,7 +331,7 @@ eval select $mysql_errno as "after_!errn
--exec illegal_command
--cat_file does_not_exist
--perl
- exit(1);
+ exit(2);
EOF
# ----------------------------------------------------------------------------
=== modified file 'mysql-test/t/wait_timeout.test'
--- a/mysql-test/t/wait_timeout.test 2009-03-06 14:56:17 +0000
+++ b/mysql-test/t/wait_timeout.test 2010-10-19 11:54:28 +0000
@@ -53,7 +53,7 @@ while (!`select @aborted_clients`)
dec $retries;
if (!$retries)
{
- Failed to detect that client has been aborted;
+ die Failed to detect that client has been aborted;
}
}
--enable_query_log
@@ -108,7 +108,7 @@ while (!`select @aborted_clients`)
dec $retries;
if (!$retries)
{
- Failed to detect that client has been aborted;
+ die Failed to detect that client has been aborted;
}
}
--enable_query_log
No bundle (reason: revision is a merge).
| Thread |
|---|
| • bzr commit into mysql-trunk-mtr branch (bjorn.munch:2975) | Bjorn Munch | 19 Oct |
