From: Bjorn Munch Date: October 19 2010 1:05pm Subject: bzr commit into mysql-trunk-mtr branch (bjorn.munch:2975) List-Archive: http://lists.mysql.com/commits/121138 Message-Id: <201010191305.o9JD5lNI000653@khepri15.norway.sun.com> MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit #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).