From 92fb31f0b185dfc45f8632ac06333ec2e5e1a5c2 Mon Sep 17 00:00:00 2001 From: Aleksey Midenkov Date: Fri, 4 Aug 2023 12:10:34 +0300 Subject: [PATCH] MDEV-30836 MTR misc improvements 1. Better logging and error reporting; 2. Worker process title; 3. Some comments Worker process title example: 446209 pts/2 R+ 0:00 mysql-test-run.pl worker[01] :42146 -> :35027 versioning.view 446210 pts/2 S+ 0:00 mysql-test-run.pl worker[02] :42150 -> :35027 versioning.view 446211 pts/2 S+ 0:00 mysql-test-run.pl worker[03] :42154 -> :35027 versioning.foreign 446212 pts/2 S+ 0:00 mysql-test-run.pl worker[04] :42160 -> :35027 versioning.autoinc Manager-worker localhost socket connection is represented by a pair :source -> :destination ports. -vv Now adds --verbose to mysqltest as well, see var/mysqltest.log for the output. --- mysql-test/lib/My/Test.pm | 2 +- mysql-test/lib/mtr_report.pm | 1 + mysql-test/mysql-test-run.pl | 52 +++++++++++++++++++++++------------- 3 files changed, 35 insertions(+), 20 deletions(-) diff --git a/mysql-test/lib/My/Test.pm b/mysql-test/lib/My/Test.pm index 49ce2fb5af9..56e7cf6d8a4 100644 --- a/mysql-test/lib/My/Test.pm +++ b/mysql-test/lib/My/Test.pm @@ -111,7 +111,7 @@ sub read_test { $serialized =~ s/\\([0-9a-fA-F]{2})/chr(hex($1))/eg; my $test= Storable::thaw($serialized); use Data::Dumper; - die "wrong class (hack attempt?): ".ref($test)."\n".Dumper(\$test, $serialized) + confess "Not My::Test: ". ref($test). "\n". Dumper(\$test, $serialized) unless ref($test) eq 'My::Test'; resfile_from_test($test) if $::opt_resfile; return $test; diff --git a/mysql-test/lib/mtr_report.pm b/mysql-test/lib/mtr_report.pm index 2a8ed65eb2c..7d944ade71a 100644 --- a/mysql-test/lib/mtr_report.pm +++ b/mysql-test/lib/mtr_report.pm @@ -48,6 +48,7 @@ our $timestamp= 0; our $timediff= 0; our $name; our $verbose; +# TODO: no option for that? Why is it different from $verbose? our $verbose_restart= 0; our $timer= 1; our $tests_total; diff --git a/mysql-test/mysql-test-run.pl b/mysql-test/mysql-test-run.pl index 4d1b3cd6aa5..e2c025bd57c 100755 --- a/mysql-test/mysql-test-run.pl +++ b/mysql-test/mysql-test-run.pl @@ -579,6 +579,7 @@ sub run_test_server ($$$) { my $s= IO::Select->new(); my $childs= 0; + my %names; $s->add($server); while (1) { if ($opt_stop_file) @@ -592,14 +593,18 @@ sub run_test_server ($$$) { mark_time_used('admin'); my @ready = $s->can_read(1); # Wake up once every second - mtr_debug("Got ". (0 + @ready). " connection(s)"); + if (@ready > 0) { + mtr_verbose2("Got ". (0 + @ready). " connection(s)"); + } mark_time_idle(); + my $i= 0; foreach my $sock (@ready) { + ++$i; if ($sock == $server) { # New client connected ++$childs; my $child= $sock->accept(); - mtr_verbose2("Client connected (got ${childs} childs)"); + mtr_verbose2("Connection ${i}: Worker connected (got ${childs} childs)"); $s->add($child); print $child "HELLO\n"; } @@ -608,7 +613,7 @@ sub run_test_server ($$$) { if (!defined $line) { # Client disconnected --$childs; - mtr_verbose2("Child closed socket (left ${childs} childs)"); + mtr_verbose2((exists $names{$sock} ? $names{$sock} : "Worker"). " closed socket (left ${childs} childs)"); $s->remove($sock); $sock->close; next; @@ -744,8 +749,9 @@ sub run_test_server ($$$) { push(@$completed, $result); } - elsif ($line eq 'START'){ - ; # Send first test + elsif ($line=~ /^START (.*)$/){ + # Send first test + $names{$sock}= $1; } elsif ($line eq 'WARNINGS'){ my $fake_test= My::Test::read_test($sock); @@ -828,7 +834,7 @@ sub run_test_server ($$$) { # At this point we have found next suitable test $next= splice(@$tests, $i, 1); last; - } + } # for(my $i= 0; $i <= @$tests; $i++) # Use second best choice if no other test has been found if (!$next and defined $second_best){ @@ -847,11 +853,11 @@ sub run_test_server ($$$) { } else { # No more test, tell child to exit - #mtr_report("Saying BYE to child"); + mtr_verbose2("Saying BYE to ". $names{$sock}); print $sock "BYE\n"; - } - } - } + } # else (!$next) + } # else ($sock != $server) + } # foreach my $sock (@ready) if (!IS_WINDOWS) { foreach my $pid (keys %$children) @@ -911,7 +917,10 @@ sub run_worker ($) { # -------------------------------------------------------------------------- # Set worker name # -------------------------------------------------------------------------- - report_option('name',"worker[$thread_num]"); + report_option('name',"worker[". sprintf("%02d", $thread_num). "]"); + my $proc_title= basename($0). " ${mtr_report::name} :". $server->sockport(). " -> :${server_port}"; + $0= $proc_title; + mtr_verbose2("Running at PID $$"); # -------------------------------------------------------------------------- # Set different ports per thread @@ -937,7 +946,7 @@ sub run_worker ($) { } # Ask server for first test - print $server "START\n"; + print $server "START ${mtr_report::name}\n"; mark_time_used('init'); @@ -945,6 +954,7 @@ sub run_worker ($) { chomp($line); if ($line eq 'TESTCASE'){ my $test= My::Test::read_test($server); + $0= $proc_title. " ". $test->{name}; # Clear comment and logfile, to avoid # reusing them from previous test @@ -961,11 +971,12 @@ sub run_worker ($) { run_testcase($test, $server); #$test->{result}= 'MTR_RES_PASSED'; # Send it back, now with results set + mtr_verbose2('Writing TESTRESULT'); $test->write_test($server, 'TESTRESULT'); mark_time_used('restart'); } elsif ($line eq 'BYE'){ - mtr_report("Server said BYE"); + mtr_verbose2("Manager said BYE"); # We need to gracefully shut down the servers to see any # Valgrind memory leak errors etc. since last server restart. if ($opt_warnings) { @@ -1856,7 +1867,7 @@ sub client_debug_arg($$) { if ( $opt_debug ) { mtr_add_arg($args, - "--loose-debug=$debug_d:t:A,%s/log/%s.trace", + "--loose-debug=d,info,warning,warnings:t:A,%s/log/%s.trace", $path_vardir_trace, $client_name) } } @@ -4046,9 +4057,8 @@ sub run_testcase ($$) { } return ($res == 62) ? 0 : $res; - } - - if ($proc) + } # if ($proc and $proc eq $test) + elsif ($proc) { # It was not mysqltest that exited, add to a wait-to-be-started-again list. $keep_waiting_proc{$proc} = 1; @@ -4077,7 +4087,7 @@ sub run_testcase ($$) { { # do nothing } - } + } # foreach my $wait_for_proc next; @@ -5457,7 +5467,11 @@ sub start_mysqltest ($) { mtr_init_args(\$args); mtr_add_arg($args, "--defaults-file=%s", $path_config_file); - mtr_add_arg($args, "--silent"); + if ($opt_verbose > 1) { + mtr_add_arg($args, "--verbose"); + } else { + mtr_add_arg($args, "--silent"); + } mtr_add_arg($args, "--tmpdir=%s", $opt_tmpdir); mtr_add_arg($args, "--character-sets-dir=%s", $path_charsetsdir); mtr_add_arg($args, "--logdir=%s/log", $opt_vardir);