List:Commits« Previous MessageNext Message »
From:Bjorn Munch Date:October 18 2010 7:42am
Subject:bzr commit into mysql-5.5-mtr branch (bjorn.munch:3098) Bug#55135
View as plain text  
#At file:///home/bm136801/my/timing-55/ based on revid:bjorn.munch@stripped

 3098 Bjorn Munch	2010-10-18
      Bug #55135 Collect times used in test execution phases in mtr
      Adding option --report-times
      Can't collect times if test run is aborted

    modified:
      mysql-test/lib/mtr_misc.pl
      mysql-test/mysql-test-run.pl
=== modified file 'mysql-test/lib/mtr_misc.pl'
--- a/mysql-test/lib/mtr_misc.pl	2010-06-07 08:47:04 +0000
+++ b/mysql-test/lib/mtr_misc.pl	2010-10-18 07:40:44 +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/mysql-test-run.pl'
--- a/mysql-test/mysql-test-run.pl	2010-09-30 10:53:36 +0000
+++ b/mysql-test/mysql-test-run.pl	2010-10-18 07:40:44 +0000
@@ -235,6 +235,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 +348,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 +421,7 @@ sub main {
 	$opt_tmpdir= "$opt_tmpdir/$child_num";
       }
 
+      init_timers();
       run_worker($server_port, $child_num);
       exit(1);
     }
@@ -429,6 +434,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,6 +481,8 @@ sub main {
 		 $opt_gcov_msg, $opt_gcov_err);
   }
 
+  print_total_times($opt_parallel) if $opt_report_times;
+
   mtr_report_stats("Completed", $completed);
 
   exit(0);
@@ -648,6 +657,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 +791,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 +811,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 {
@@ -978,6 +996,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,
@@ -3163,6 +3182,7 @@ sub check_testcase($$)
 
 	if ( keys(%started) == 0){
 	  # All checks completed
+	  mark_time_used('check');
 	  return 0;
 	}
 	# Wait for next process to exit
@@ -3220,6 +3240,7 @@ test case was executed:\n";
     # Kill any check processes still running
     map($_->kill(), values(%started));
 
+    mark_time_used('check');
     return $result;
   }
 
@@ -3529,6 +3550,7 @@ sub run_testcase ($) {
       return 1;
     }
   }
+  mark_time_used('restart');
 
   # --------------------------------------------------------------------
   # If --start or --start-dirty given, stop here to let user manually
@@ -3581,6 +3603,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 +3651,7 @@ sub run_testcase ($) {
     }
     mtr_verbose("Got $proc");
 
+    mark_time_used('test');
     # ----------------------------------------------------
     # Was it the test program that exited
     # ----------------------------------------------------
@@ -4030,6 +4055,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 +4088,7 @@ sub check_warnings ($) {
     # Kill any check processes still running
     map($_->kill(), values(%started));
 
+    mark_time_used('ch-warn');
     return $result;
   }
 
@@ -5025,6 +5052,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);
@@ -5660,6 +5689,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);
 


Attachment: [text/bzr-bundle] bzr/bjorn.munch@oracle.com-20101018074044-zech3hl61cl1ag0c.bundle
Thread
bzr commit into mysql-5.5-mtr branch (bjorn.munch:3098) Bug#55135Bjorn Munch18 Oct