Bug #55135 Collect times used in test execution phases in mtr

Adding option --report-times
Can't collect times if test run is aborted

2 files changed, 116 insertions, 1 deletions

diff --git a/mysql-test/lib/mtr_misc.pl b/mysql-test/lib/mtr_misc.pl
index 32960d866ce..dc9928d37c5 100644
--- a/mysql-test/lib/mtr_misc.pl
+++ b/mysql-test/lib/mtr_misc.pl
@@ -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;
diff --git a/mysql-test/mysql-test-run.pl b/mysql-test/mysql-test-run.pl
index e6d988dfba6..fe71fe69ad4 100755
--- a/mysql-test/mysql-test-run.pl
+++ b/mysql-test/mysql-test-run.pl
@@ -236,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;
 
@@ -348,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
@@ -418,6 +422,7 @@ sub main {
 	$opt_tmpdir= "$opt_tmpdir/$child_num";
       }
 
+      init_timers();
       run_worker($server_port, $child_num);
       exit(1);
     }
@@ -430,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;
@@ -475,6 +482,8 @@ 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;
@@ -651,6 +660,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");
 	}
@@ -782,7 +794,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);
@@ -800,16 +814,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 {
@@ -982,6 +1000,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,
@@ -3169,6 +3188,7 @@ sub check_testcase($$)
 
 	if ( keys(%started) == 0){
 	  # All checks completed
+	  mark_time_used('check');
 	  return 0;
 	}
 	# Wait for next process to exit
@@ -3226,6 +3246,7 @@ test case was executed:\n";
     # Kill any check processes still running
     map($_->kill(), values(%started));
 
+    mark_time_used('check');
     return $result;
   }
 
@@ -3535,6 +3556,7 @@ sub run_testcase ($) {
       return 1;
     }
   }
+  mark_time_used('restart');
 
   # --------------------------------------------------------------------
   # If --start or --start-dirty given, stop here to let user manually
@@ -3587,6 +3609,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);
@@ -3633,6 +3657,7 @@ sub run_testcase ($) {
     }
     mtr_verbose("Got $proc");
 
+    mark_time_used('test');
     # ----------------------------------------------------
     # Was it the test program that exited
     # ----------------------------------------------------
@@ -4036,6 +4061,7 @@ sub check_warnings ($) {
 
 	if ( keys(%started) == 0){
 	  # All checks completed
+	  mark_time_used('ch-warn');
 	  return $result;
 	}
 	# Wait for next process to exit
@@ -4068,6 +4094,7 @@ sub check_warnings ($) {
     # Kill any check processes still running
     map($_->kill(), values(%started));
 
+    mark_time_used('ch-warn');
     return $result;
   }
 
@@ -5031,6 +5058,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);
@@ -5668,6 +5697,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);