List:Commits« Previous MessageNext Message »
From:Bjorn Munch Date:October 19 2010 1:06pm
Subject:bzr push into mysql-trunk-mtr branch (bjorn.munch:2974 to 2975)
View as plain text  
 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
 2974 Bjorn Munch	2010-10-01 [merge]
      upmerge 20304

    modified:
      client/mysqltest.cc
=== 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: useless for push emails).
Thread
bzr push into mysql-trunk-mtr branch (bjorn.munch:2974 to 2975) Bjorn Munch19 Oct