diff --git a/bin/pt-kill b/bin/pt-kill index c78f0abc..fe71ea67 100755 --- a/bin/pt-kill +++ b/bin/pt-kill @@ -1129,6 +1129,7 @@ if ( PTDEBUG ) { # ########################################################################### { package Lmo::Utils; + use strict; use warnings qw( FATAL all ); require Exporter; @@ -1136,7 +1137,12 @@ our (@ISA, @EXPORT, @EXPORT_OK); BEGIN { @ISA = qw(Exporter); - @EXPORT = @EXPORT_OK = qw(_install_coderef _unimport_coderefs _glob_for _stash_for); + @EXPORT = @EXPORT_OK = qw( + _install_coderef + _unimport_coderefs + _glob_for + _stash_for + ); } { @@ -1320,7 +1326,6 @@ sub meta { return Lmo::Meta->new(class => $class); } - 1; } # ########################################################################### @@ -3264,10 +3269,24 @@ sub parse_event { $new_query = 1; } elsif ( $curr->[INFO] && defined $curr->[TIME] - && $query_start - $etime - $prev->[START] > $fudge ) { - PTDEBUG && _d('Query restarted; new query', - $query_start, $etime, $prev->[START], $fudge); - $new_query = 1; + && $query_start - $etime - $prev->[START] > $fudge) + { + my $ms = $self->{MasterSlave}; + + my $is_repl_thread = $ms->is_replication_thread({ + Command => $curr->[COMMAND], + User => $curr->[USER], + State => $curr->[STATE], + Id => $curr->[ID]}); + if ( $is_repl_thread ) { + PTDEBUG && + _d(q{Query has restarted but it's a replication thread, ignoring}); + } + else { + PTDEBUG && _d('Query restarted; new query', + $query_start, $etime, $prev->[START], $fudge); + $new_query = 1; + } } if ( $new_query ) { @@ -4951,6 +4970,8 @@ use warnings FATAL => 'all'; use English qw(-no_match_vars); use constant PTDEBUG => $ENV{PTDEBUG} || 0; +use Time::HiRes qw(sleep); + sub new { my ( $class, %args ) = @_; my $self = { diff --git a/bin/pt-query-digest b/bin/pt-query-digest index a4b29c26..dbb0b194 100755 --- a/bin/pt-query-digest +++ b/bin/pt-query-digest @@ -3215,10 +3215,24 @@ sub parse_event { $new_query = 1; } elsif ( $curr->[INFO] && defined $curr->[TIME] - && $query_start - $etime - $prev->[START] > $fudge ) { - PTDEBUG && _d('Query restarted; new query', - $query_start, $etime, $prev->[START], $fudge); - $new_query = 1; + && $query_start - $etime - $prev->[START] > $fudge) + { + my $ms = $self->{MasterSlave}; + + my $is_repl_thread = $ms->is_replication_thread({ + Command => $curr->[COMMAND], + User => $curr->[USER], + State => $curr->[STATE], + Id => $curr->[ID]}); + if ( $is_repl_thread ) { + PTDEBUG && + _d(q{Query has restarted but it's a replication thread, ignoring}); + } + else { + PTDEBUG && _d('Query restarted; new query', + $query_start, $etime, $prev->[START], $fudge); + $new_query = 1; + } } if ( $new_query ) { diff --git a/lib/Processlist.pm b/lib/Processlist.pm index e53eca3b..0546b1ce 100644 --- a/lib/Processlist.pm +++ b/lib/Processlist.pm @@ -245,14 +245,28 @@ sub parse_event { $new_query = 1; } elsif ( $curr->[INFO] && defined $curr->[TIME] - && $query_start - $etime - $prev->[START] > $fudge ) { + && $query_start - $etime - $prev->[START] > $fudge) + { # If the query's recalculated start time minus its previously # calculated start time is greater than the fudge factor, then # the query has restarted. I.e. the new start time is after # the previous start time. - PTDEBUG && _d('Query restarted; new query', - $query_start, $etime, $prev->[START], $fudge); - $new_query = 1; + my $ms = $self->{MasterSlave}; + + my $is_repl_thread = $ms->is_replication_thread({ + Command => $curr->[COMMAND], + User => $curr->[USER], + State => $curr->[STATE], + Id => $curr->[ID]}); + if ( $is_repl_thread ) { + PTDEBUG && + _d(q{Query has restarted but it's a replication thread, ignoring}); + } + else { + PTDEBUG && _d('Query restarted; new query', + $query_start, $etime, $prev->[START], $fudge); + $new_query = 1; + } } if ( $new_query ) { diff --git a/t/lib/Processlist.t b/t/lib/Processlist.t index afe088ba..e22a54df 100644 --- a/t/lib/Processlist.t +++ b/t/lib/Processlist.t @@ -335,9 +335,116 @@ is_deeply( "New query2_2 is active, starting at 05:08" ); + +# ########################################################################### +# pt-query-digest --processlist: Duplicate entries for replication thread +# https://bugs.launchpad.net/percona-toolkit/+bug/1156901 +# ########################################################################### + +# This is basically the same thing as above, but we're pretending to +# be a repl thread, so it should behave differently. + +$pl = Processlist->new(MasterSlave=>$ms); + +parse_n_times( + 1, + code => sub { + return [ + [ 2, 'system user', 'localhost', 'test', 'Query', 0, 'executing', 'query2_2'], + ], + }, + time => Transformers::unix_timestamp('2001-01-01 00:05:03'), + etime => 3.14159, +); + +is_deeply( + $pl->_get_active_cxn(), + { + 2 => [ + 2, 'system user', 'localhost', 'test', 'Query', 0, 'executing', 'query2_2', + Transformers::unix_timestamp('2001-01-01 00:05:03'), # START + 3.14159, # ETIME + Transformers::unix_timestamp('2001-01-01 00:05:03'), # FSEEN + { executing => 0 }, + ], + }, + 'query2_2 just started', +); + +# And there is no event on cxn 2. +is( + scalar @events, + 0, + 'query2_2 has not fired yet', +); + +parse_n_times( + 1, + code => sub { + return [ + [ 2, 'system user', 'localhost', 'test', 'Query', 0, 'executing', 'query2_2'], + ], + }, + time => Transformers::unix_timestamp('2001-01-01 00:05:05'), + etime => 2.718, +); + +is( + scalar @events, + 0, + 'query2_2 has not fired yet, same as with normal queries', +); + +is_deeply( + $pl->_get_active_cxn(), + { + 2 => [ + 2, 'system user', 'localhost', 'test', 'Query', 0, 'executing', 'query2_2', + Transformers::unix_timestamp('2001-01-01 00:05:03'), + 3.14159, + Transformers::unix_timestamp('2001-01-01 00:05:03'), + { executing => 2 }, + ], + }, + 'Cxn 2 still active with query starting at 05:03', +); + +# Same as above but five seconds and a half later +parse_n_times( + 1, + code => sub { + return [ + [ 2, 'system user', 'localhost', 'test', 'Query', 0, 'executing', 'query2_2'], + ], + }, + time => Transformers::unix_timestamp('2001-01-01 00:05:08.500'), + etime => 0.123, +); + +is_deeply( + \@events, + [], + 'Original query2_2 not fired because we are a repl thrad', +); + +is_deeply( + $pl->_get_active_cxn(), + { + 2 => [ + 2, 'system user', 'localhost', 'test', 'Query', 0, 'executing', 'query2_2', + Transformers::unix_timestamp('2001-01-01 00:05:03'), # START + 3.14159, # ETIME + Transformers::unix_timestamp('2001-01-01 00:05:03'), # FSEEN + { executing => 5.5 }, + ], + }, + "Old query2_2 is active because we're a repl thread, but executing has updated" +); + # ########################################################################### # Issue 867: Make mk-query-digest detect Lock_time from processlist # ########################################################################### +$ms = new MasterSlave(OptionParser=>1,DSNParser=>1,Quoter=>1); $pl = Processlist->new(MasterSlave=>$ms); # For 2/10ths of a second, the query is Locked. First time we see this