From: Bjorn Munch Date: October 18 2010 7:42am Subject: bzr commit into mysql-5.5-mtr branch (bjorn.munch:3098) Bug#55135 List-Archive: http://lists.mysql.com/commits/120934 X-Bug: 55135 Message-Id: <201010180742.o9I7gZjJ026908@khepri15.norway.sun.com> MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="===============1805385747==" --===============1805385747== MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Content-Disposition: inline #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); --===============1805385747== 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/timing-55/ # testament_sha1: aef5ce812c7d24b62126284fd38dcd403478b407 # timestamp: 2010-10-18 09:42:35 +0200 # base_revision_id: bjorn.munch@stripped\ # lwe80a2k6hcrqre6 # # Begin bundle IyBCYXphYXIgcmV2aXNpb24gYnVuZGxlIHY0CiMKQlpoOTFBWSZTWatjILgABJ7/gHEwBAB+//// fmNeD7////tgCZzQFsL7Qcopg7dprc2KtSzalGuwkkptExE9CbTJRsaaU9Hqn5ERo0GjQGQA0AEo gmEyaKeo0mCbSMnpGgAANBoAGgaHGRpkxNBkyYTTIGQ0BoDTJoYATQGEiIIU00yJgajBPRJkzUYE 009TQDQYQemocZGmTE0GTJhNMgZDQGgNMmhgBNAYSRAQI00BGQpnpNT9RoQepjUyaDQAANFxWaSY Nrf7GcXPQ+cJE8/SpVWmwa1WwouL+evL2nT0X+LWTa/SDQsxDcdDI+VIeiNo5WoJd7tZ4oQSby0B /AxJE1TrvYTT8q6GWMAA5qELcjZZyZyO2qXyteypgYYxSruKlI0PBw229uBviEgJOkGBytGiYY0i hSEMYkU6tfGEM/Xkw73DY7CPHFRrVl7bHu2atluYrlK+MzfKrnBzA9FG22226GCpZqPjwaVy+aNm 3l0nb4C4wbBsQb4r5z3iWZ5XnzuOR8+t8+vXrm+wlGHQypQvNsYuwu8h2c2yJs4c0i18ZycYxjhh ahORFWq2eWVDZ9+vUxtb9Dj82dncru8nvMvDPB2Pv1xMaK0d6PlZPnnQWL82NZzQ9nJ4WwkcA2rM 0UKksFL9TXEbnyBkGsnwsSCOIUJTbAhCV8EQxBHI+KTt24rzJMG9qtcfLVGUatO0z97Jlad2Au0e ziDc3cMM1xVaskeIglHracEMbExgx+UTUe+BehknXGy0ijAzBtbpnkGwgagaoYDGMbGj1QQqKCGj uFxtuZIY3KScLW3GthTex4eunBubDUR4l8HvNKWcM57zTxW6Kwx1xNnw4jJz+UdUiUTMWTSOljMo OQrdmebmVpSMXQW9DpsFUFMPNQ8pgBhj49cYWS1ITCU0x6N01DPMmf1bNIXG0d/zQlSEecN6CZhN CYH1SogGBeNGD02BwNNIUi7V0kqgMVshOk3CauI/uTXMXG8Ck2gUSV1zm9iMCHTH4agHayCC6C+3 0RUleSm8cQrOefZt91WfRaE27gkc2FwbMxZiZX6syLtvdcA8uu7R/eRka+GkDSBqNrBlklmwZ7tb a5WNHRSOPWFGQrNrUpUjaElbMnYUIPqgUuqxqgjoNSlTi7568M19LovqFJrdFo1YKOvNLX3sGKgq LB1mpaYxX4TGGZumVKl50GQHRym7bDWxXGjL88kCJEBUeDgiQgMO2LaiQFnPEqUJyNlJl166L4YR RDnWYbaXtRvQaCspkMXWY5tGVfgUIj7t97XFge3GZJyawTu86hwcGU99aYJK8dKFx/ivRA31gaSG ikc9ESMBasyzAiPmSnCM9sa6G1stqqupmF5QiTXkTTxnVtaq1wm+I94PJ4D9ceEHAtGJxqZWvRss ghPXM0w33jmxiXLwyjRgC6EcwzkMjlDJYGd9zZX7hPKWs+Rdg2q1rEa5yOZZeIWuvMmNwiSZli+i usdKZUxGY6du1rZKdud6kCw0V23TTCtAOzosUWu31h1M9PjmTBkNBDXVSJiFT69HaOl2GlzwHqX0 W9zxa43sGWQ5rJE7jfMXkYPYXsbY2P84z+U/BC6vVU9b9CFr3cwxjb+FeYnMS2V/0rSljsP46q9r Owd3xkcM8pu/E/E1WNKT31qhLk36BIVIW+ASB1CYi7Y6q4xmEjfea+LCnHhCzntNlxIO8cUuZz10 ZEKjU+YhiSyrTAqBkUQ7thK7xR7k2REXn5XeDXA1AHMhATmyYbeEjexrlBer5xGjo9J6ZnAbHCR6 jv2zM2e6BuDaa0w7swjsZUSYjlRzsJDlTUnE9d+XYewzQRz7YSZruNqi/3BIB0LhAKRmyI9gEEKw mu8S10+BMLLyJwPYyEWmRs2SwXUmPAYwyCgNbFE+lZXI2LwenP7qNhqRdyeowrLNpymKD+I41fsN Gyn2Gj7hirNJcpTxh7uL3a+1YLj0GCzN2DGffk1GeBoRJCUS0NW0tL0gEAp4xZwwb9bwSrrrobjr U992B0+ZuLscVHk+7App3uhDaZCYalx/OUiaebRC193imwcmrCQzT62pTM0dMwAa9KjYPcwI0IhW Dw4HQqgYURZBgVStXjGPCHDhuGOqG7xFU5sXgGtD4zrMSpxxLyW5uRzXD+ZljA62SiOqnrN8VwiQ YSNQr+wbcpvJCDRcfNsnAjrkspEK8a/27bO3DT0oa7hiwmZiAOAk4qhRLvsIAiUWpESMb4Gsm6Er 52tkGZKrZplkDJmChcuCO7OZgUebVGo0TnPEVPk5IXZ1cDtZHrTX6BBQVmtGUyzaCfUPy8ZAwbXB wAUIpAhgDULuDJUQmNjE0pmdaPJlbb7GZs5BdPmE9LXTaAzeBTaxDIEuRfa20a2yNR6HbYNxMGmN CS1sOJslx85fSdFf7M4/rQuhzV4HWhQTjthWoeW/tMxp24HSZ3Y6qn9VcBuTZl6ITUF+MtK7otoY rUaFZFfAQiGLPjCR2dt1wng8htXbTEMTTrAYcGM8lyXZhEoofKyaLpKM2Ze9l3so+WeDXJVuOSE9 DlnGWMSsEWsngqMWslVl2ieKvcKA0ZM9jhghXTElff/LRQEoLJphsZbmWCQCdRzZ9a85K9GhPywz 2Gul7A0XHVMIUiCmrqUrgxvZLPPp4BQQhlo4OqS1oKgFos6cHQmz9U5+Fd5VWIssEwiGss+wURRb cHHuleg6MqRSw39LDytLEMYE6usK1UIWYOCWriEVpCBizl1iHLgzec+tma+4THPkjOkswNRhSwQ5 fuEUOUuxSGMrdO9lrkQJjhKReg6UHAOJZOapQosKUiPVI4xiS2pKQcKhUUhTrzoJpWNGtNmgMFu5 mZjZzNIIQhZfntlQY99AcAdOi5RiBaOM6S0qmnTfksjIWlWIIrkEIqx2YMaC6fSbO2oLpt9WNbkS pfVl/1iFlVL+RxQsCfpbKkLMoAhXKcB1OzU5FjRhoRmLHSnHgGjeN1JpMYbZ6eRvuREZBuJoDHJO 5QoeLI45EEOMvHTthcKPAW9ppltFsvooDUMN72KDkgL5/8XckU4UJCrYyC4A --===============1805385747==--