From: Bjorn Munch Date: October 19 2010 12:09pm Subject: bzr commit into mysql-5.5-mtr branch (bjorn.munch:3100) Bug#55135 List-Archive: http://lists.mysql.com/commits/121129 X-Bug: 55135 Message-Id: <201010191209.o9JC985K027803@khepri15.norway.sun.com> MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="===============0917962693==" --===============0917962693== MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Content-Disposition: inline #At file:///home/bm136801/my/pidwait-55/ based on revid:bjorn.munch@stripped 3100 Bjorn Munch 2010-10-19 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-19 12:08:46 +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-10-13 11:07:28 +0000 +++ b/mysql-test/mysql-test-run.pl 2010-10-19 12:08:46 +0000 @@ -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); --===============0917962693== MIME-Version: 1.0 Content-Type: text/bzr-bundle; charset="us-ascii"; name="bzr/bjorn.munch@stripped" Content-Transfer-Encoding: 7bit Content-Disposition: inline # Bazaar merge directive format 2 (Bazaar 0.90) # revision_id: bjorn.munch@stripped # target_branch: file:///home/bm136801/my/pidwait-55/ # testament_sha1: be762f4960224e5b4eb35b9c75f416c70e86ebbc # timestamp: 2010-10-19 14:09:08 +0200 # source_branch: file:///home/bm136801/my/pidwait-55/ # base_revision_id: bjorn.munch@stripped\ # 6jkjct2yguztbomw # # Begin bundle IyBCYXphYXIgcmV2aXNpb24gYnVuZGxlIHY0CiMKQlpoOTFBWSZTWWqqIBIABJJ/gHEwBAB+//// fmNeD7////tgCXzr6G97jxevAAnvNBazIaiHvbq2PCUUNTCamaTxTNQ9R6aE0D0mgNAaADQAASgg mImNJPSmiaflNJhAGIAAAANB6g0JpoKNR6gHqekDQaNNABoAAAAAEiIJNT0EFNqe0SeU2aUNqabT JqHqNA0Gj1NNBsocZGmTE0GTJhNMgZDQGgNMmhgBNAYSRJpoI0CNoARontKbVPU0ejEJo9QaAaaG mlxWaSYNrf97Nfkod8JHj8nOpCrGwa4rZqLh/j1dxlzlv6azNr9INS2iG42Mj3Uh6Y0HI1BLvdrK FECm8YEA+2hSEzK69BMvc1hTTAAAdtksGCHeglS1UthF6qnRhTKay7ipSNTs4bbe5A3rEgJOcGBu ZGGDsMkTEzoYYSJu3q2A7Hv20a8858h+T1GuHH77Hsz1bLfGVxle6ZvjVzg5geqjbbbbdDBUs1Hu +HbXJ1Rnt6Ns8O4uMG02kG+K+g9olk8bz6dkTyOdklIp5OXMlzUbNmyhemGMWYrZos8SkFWS1Wua bOJjB1HTHEnBqtHjmpn9vNwsbW/Q+LryZvVxs31E7rqvw9B8hJSZMtPhiPPdSGELcnusodEzi0XB QB8m2RQyKcFLeR4GEo0Bpu1fWZJpAniUq8yQWY46KOPwMdg+cETaoihUs49ioeNS3PjLl+1GsjUJ t2eaZDc3sMMriq1YR0EEo7WnBDGxMYMfUJqPbAuxkn3RnaRRgZBp3jRINhA1A1QwGMY2NH1QQqKC GjeLjbcyQxuUk4XK3HKwTZac/umzZK2TvxXwbKyUGM8LJQm4z9UXYaNJfuwmPu8R9yKxMxwwVPXS cwOhdYF/KG/PDgZhi6He1leyCiHZeO0rwenmjCiORCYSnTHfbOoWTnFVRS7GQbGsmZ36GEMXW0rw qA4ijQpBelo85mCAMMV2K5ojTUCtGVWawdEyJwAjB5BQKBH2EhEHeW2m6SzMhlMZ46fK6oWDBYBK 4uJ7fZkFVYpWJ3MQNQrZcI7m32rSQPC8rG4RJHLgwVyOJxyLaslcvPvr4XnkBqanWOXOyXJwzAzR IXuz20WER46bYzl2BgqCUgBgNWo8AziliFIyCFAeWrIdDTrvTPwBTsV7Xk9s3nrmESioKMzaZDFO kXsrKiOqaws9CbjUpcYscS5lsd6YvadvID6D/dNcrXXeMUHBguMOhcY5u64AYCtsLPuYVj1IPqm4 pz6N2m5hTO2OcHXNea31Oh3dvBCWJxDvPkuJuFvl33eXdWuKcB1HP+O3ntylPoPTle88FWQGJ3JQ rDV+qFnmTfeLVVurYN+nlNwe+l7NW2bPLS5HTB+EJ6inidDFR8Zrd2j4jaodWvPgMToud00W0XDF Hs3vgKZl9UDaZClFhLhhWOumRYnhjBsc3i9MlQIJbvldsThkuOZmc2ShYK9da8M2H2fvwYTXaOaw yZJMCklglEWu/tD6GdnmmTBkNBDXlpExCp06vAdLsNtzvn0r5Lfs8zXE9oxxHNZIndHyF4GD2l2t sbH640dRlQTFxMONeBBOGWEUUVV9WXRuEbVRn0MccrH4eWJnzY+Q0m2D54bjn+B5GmcxJNatLpbb ZggER1aAQA7RMIkzDRUhhmEjlBpigVsT0Bw9VGSaK79CFFE+nAzlUdf2Yiy4TG1FuiT/v2U7NIGw AyRcWTwYa0ImVssYLw9gjFyNB4aCRuInps1UZpFmBzOHQdKYf30gZsoNNkPAr5I9DCRLoUTwPXXX DyJY8yzFj276VM/5AyFqcOEp2RM6FSRXiJc84vtBvs5JwL7IRuL1tsZtxgpwhjoCmFtckY9iqMmZ FgRVlnx/DpKp9NBCq5NqhcY8NdsCHkZEP1nFo6IEKauyBGchuyS1Xtqxk9fnMr73iNpZPnGZ+DJ8 ziTSiqEth5gqkKbA44JK+JMGduUMBEgovQzLevJMBbgbsXdB5dHvg5Dz+rApu7+KG0yEw1rvhIie vRC8XHwTYOPXhIVw9bKCYvP1wcAzYU9Z+bAPhQ6nC6g3qIFEyJ0F8oSqVwxuDjzBlHOrZADhQs5a FQfUdRhICmIbRKlwtLsjMandnojpluYyp2cLYhXFETUEfpFs5GAta/VS7dyYZhBGyj7awSrHc5UF jvxxAP2SVRgYS9q6BSXBkAElLaiSMkZmw96Uj4tkGZLbv11UhiZgkcVqR3YCxLeyI6ueNI0xkDWW h5is7bkK/drO5hSzCDMbzpRcGUy3gMOIy7ifn6SZg63DMiZw5hegMayITF9idKcsWLz46qvazNYQ W3kJ5VOnqDKK1IZAlxrtbaOZsjWq5jbTBpjQkt7Diwro0lcoyVft84/sQpBpgZNrrCoJx2v00h1X /mNo29yB0md6Oip3VcBuzZl6ITUF/GWlcItIxWo0KyK8xCIaNGaEj3+F1wGzoNN20xDE06wGfiZp qudbM9C6npadISXOFbtrva6mq+W+h5JUXi5Cih1oGWMSuEWMogrcPQVrh26+QFKVG/kKJsx6OLjB OqPChKmf5S7BRNgKjcBuo4suTKmsC1VaaV7iqZE1HiBK/OMrmqGRuGimB1AQTa3WemeKVsPTmE46 GWLW6lHnQUAFQrE4OhNZnM3AIFEhGIIwQQylRMKQUqUGZih9wXJqisDPWMPOqJQKMIsWTLDBHemT AibeEIJcHTRi1EGKws+k8mZr1YmO7GjAkrAaTCjYhy9aIkcY+ZRGbmO7ra+CpJMdBSL0HSg4BxLJ yrDoUWFgtGD+qAz0vAlpSgDhSFIoino0IJ0uQVPTRbjDQuDW2zf1uoTM6M+rGtxnfcIAIUI2lSgG IwrIicSfHjjsly4nFKIEE9gHglGVQ0mJz9k39vAFtq78NFaIyvUMvnShcyzR4uWq8o7W5khZVME6 1m8MA+XNjWJF+1GUues31AV6gxaRsoNOBJzBNPj4Gi8iYZBaToDFkTuSJHXkPuC6ooRcXiauyIqV 2ih6MJCKUCQCTMoDELU/SoOJAJm/xdyRThQkGqqIBIA= --===============0917962693==--