Percona Toolkit moved to https://jira.percona.com/projects/PT

Merge lp:~percona-toolkit-dev/percona-toolkit/fix-1156901-skip-retry-check-for-repl-threads into lp:percona-toolkit/2.2

  1. fix-1156901-skip-retry-check-for-repl-threads
  2. Merge into 2.2
Proposed by Daniel Nichter
Status: Merged
Merged at revision: 576
Proposed branch: lp:~percona-toolkit-dev/percona-toolkit/fix-1156901-skip-retry-check-for-repl-threads
Merge into: lp:percona-toolkit/2.2
Diff against target: 372 lines (+186/-24)
4 files modified
bin/pt-kill (+27/-6)
bin/pt-query-digest (+34/-14)
lib/Processlist.pm (+18/-4)
t/lib/Processlist.t (+107/-0)
To merge this branch: bzr merge lp:~percona-toolkit-dev/percona-toolkit/fix-1156901-skip-retry-check-for-repl-threads
Reviewer Review Type Date Requested Status
Daniel Nichter Approve
Review via email: mp+159177@code.launchpad.net
To post a comment you must log in.
Revision history for this message
Daniel Nichter (daniel-nichter) wrote :

46 + my $is_repl_thread = !$ms->is_replication_thread({
164 + my $is_repl_thread = $ms->is_replication_thread({

Looks like something wasn't updated?

Also, I think you can call it like: $ms->is_replication_thread($curr) since $curr is already the proclist hash.

51 + if ( !$is_repl_thread ) {
52 + PTDEBUG && _d('Query restarted; new query',
53 + $query_start, $etime, $prev->[START], $fudge);
54 + $new_query = 1;
55 + }
56 + elsif ( PTDEBUG ) {

Because we're checking if it's a repl thread, the same positive check first makes sense (else the code reads: "is it a repl thread? is it not a repl thread?"):

if ( $is_repl_thread ) {
   PTDEBUG && _d("Query has restarted but it's a replication thread, ignoring");
}
else {
   # Query has restarted but it's not a replication thread, so treat it as a new query.
   ...
   $new_query = 1;
}

57 + _d(q'Query has a start time beyond the fudge factor, ',
58 + q'but not counting it as a new query because, ',
59 + q{it's a replication thread});

Please always exercise consistency: we've never used q'' before, and it's confusing because ' is a quote char too; and the quoting changes in the same (multi) line to q{}.

review: Needs Fixing
lp:~percona-toolkit-dev/percona-toolkit/fix-1156901-skip-retry-check-for-repl-threads updated
574. By Brian Fraser

Fixes per Daniel's review

Revision history for this message
Daniel Nichter (daniel-nichter) :
review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'bin/pt-kill'
2--- bin/pt-kill 2013-04-04 21:45:50 +0000
3+++ bin/pt-kill 2013-04-16 16:03:28 +0000
4@@ -1129,6 +1129,7 @@
5 # ###########################################################################
6 {
7 package Lmo::Utils;
8+
9 use strict;
10 use warnings qw( FATAL all );
11 require Exporter;
12@@ -1136,7 +1137,12 @@
13
14 BEGIN {
15 @ISA = qw(Exporter);
16- @EXPORT = @EXPORT_OK = qw(_install_coderef _unimport_coderefs _glob_for _stash_for);
17+ @EXPORT = @EXPORT_OK = qw(
18+ _install_coderef
19+ _unimport_coderefs
20+ _glob_for
21+ _stash_for
22+ );
23 }
24
25 {
26@@ -1320,7 +1326,6 @@
27 return Lmo::Meta->new(class => $class);
28 }
29
30-
31 1;
32 }
33 # ###########################################################################
34@@ -3264,10 +3269,24 @@
35 $new_query = 1;
36 }
37 elsif ( $curr->[INFO] && defined $curr->[TIME]
38- && $query_start - $etime - $prev->[START] > $fudge ) {
39- PTDEBUG && _d('Query restarted; new query',
40- $query_start, $etime, $prev->[START], $fudge);
41- $new_query = 1;
42+ && $query_start - $etime - $prev->[START] > $fudge)
43+ {
44+ my $ms = $self->{MasterSlave};
45+
46+ my $is_repl_thread = $ms->is_replication_thread({
47+ Command => $curr->[COMMAND],
48+ User => $curr->[USER],
49+ State => $curr->[STATE],
50+ Id => $curr->[ID]});
51+ if ( $is_repl_thread ) {
52+ PTDEBUG &&
53+ _d(q{Query has restarted but it's a replication thread, ignoring});
54+ }
55+ else {
56+ PTDEBUG && _d('Query restarted; new query',
57+ $query_start, $etime, $prev->[START], $fudge);
58+ $new_query = 1;
59+ }
60 }
61
62 if ( $new_query ) {
63@@ -4951,6 +4970,8 @@
64 use English qw(-no_match_vars);
65 use constant PTDEBUG => $ENV{PTDEBUG} || 0;
66
67+use Time::HiRes qw(sleep);
68+
69 sub new {
70 my ( $class, %args ) = @_;
71 my $self = {
72
73=== modified file 'bin/pt-query-digest'
74--- bin/pt-query-digest 2013-03-20 17:53:36 +0000
75+++ bin/pt-query-digest 2013-04-16 16:03:28 +0000
76@@ -81,6 +81,7 @@
77 # ###########################################################################
78 {
79 package Lmo::Utils;
80+
81 use strict;
82 use warnings qw( FATAL all );
83 require Exporter;
84@@ -88,7 +89,12 @@
85
86 BEGIN {
87 @ISA = qw(Exporter);
88- @EXPORT = @EXPORT_OK = qw(_install_coderef _unimport_coderefs _glob_for _stash_for);
89+ @EXPORT = @EXPORT_OK = qw(
90+ _install_coderef
91+ _unimport_coderefs
92+ _glob_for
93+ _stash_for
94+ );
95 }
96
97 {
98@@ -272,7 +278,6 @@
99 return Lmo::Meta->new(class => $class);
100 }
101
102-
103 1;
104 }
105 # ###########################################################################
106@@ -3210,10 +3215,24 @@
107 $new_query = 1;
108 }
109 elsif ( $curr->[INFO] && defined $curr->[TIME]
110- && $query_start - $etime - $prev->[START] > $fudge ) {
111- PTDEBUG && _d('Query restarted; new query',
112- $query_start, $etime, $prev->[START], $fudge);
113- $new_query = 1;
114+ && $query_start - $etime - $prev->[START] > $fudge)
115+ {
116+ my $ms = $self->{MasterSlave};
117+
118+ my $is_repl_thread = $ms->is_replication_thread({
119+ Command => $curr->[COMMAND],
120+ User => $curr->[USER],
121+ State => $curr->[STATE],
122+ Id => $curr->[ID]});
123+ if ( $is_repl_thread ) {
124+ PTDEBUG &&
125+ _d(q{Query has restarted but it's a replication thread, ignoring});
126+ }
127+ else {
128+ PTDEBUG && _d('Query restarted; new query',
129+ $query_start, $etime, $prev->[START], $fudge);
130+ $new_query = 1;
131+ }
132 }
133
134 if ( $new_query ) {
135@@ -3789,6 +3808,7 @@
136 sessions => {},
137 o => $args{o},
138 fake_thread_id => 2**32, # see _make_event()
139+ null_event => $args{null_event},
140 };
141 PTDEBUG && $self->{server} && _d('Watching only server', $self->{server});
142 return bless $self, $class;
143@@ -3809,7 +3829,7 @@
144 $server .= ":$self->{port}";
145 if ( $src_host ne $server && $dst_host ne $server ) {
146 PTDEBUG && _d('Packet is not to or from', $server);
147- return;
148+ return $self->{null_event};
149 }
150 }
151
152@@ -3825,7 +3845,7 @@
153 }
154 else {
155 PTDEBUG && _d('Packet is not to or from a MySQL server');
156- return;
157+ return $self->{null_event};
158 }
159 PTDEBUG && _d('Client', $client);
160
161@@ -3843,7 +3863,7 @@
162 else {
163 PTDEBUG && _d('Ignoring mid-stream', $packet_from, 'data,',
164 'packetno', $packetno);
165- return;
166+ return $self->{null_event};
167 }
168
169 $self->{sessions}->{$client} = {
170@@ -3886,7 +3906,7 @@
171 delete $self->{sessions}->{$session->{client}};
172 return $event;
173 }
174- return;
175+ return $self->{null_event};
176 }
177
178 if ( $session->{compress} ) {
179@@ -3912,7 +3932,7 @@
180 PTDEBUG && _d('remove_mysql_header() failed; failing session');
181 $session->{EVAL_ERROR} = $EVAL_ERROR;
182 $self->fail_session($session, 'remove_mysql_header() failed');
183- return;
184+ return $self->{null_event};
185 }
186 }
187
188@@ -3927,7 +3947,7 @@
189 $self->_delete_buff($session);
190 }
191 else {
192- return; # waiting for more data; buff_left was reported earlier
193+ return $self->{null_event}; # waiting for more data; buff_left was reported earlier
194 }
195 }
196 elsif ( $packet->{mysql_data_len} > ($packet->{data_len} - 4) ) {
197@@ -3948,7 +3968,7 @@
198
199 PTDEBUG && _d('Data not complete; expecting',
200 $session->{buff_left}, 'more bytes');
201- return;
202+ return $self->{null_event};
203 }
204
205 if ( $session->{cmd} && ($session->{state} || '') eq 'awaiting_reply' ) {
206@@ -3971,7 +3991,7 @@
207 }
208
209 $args{stats}->{events_parsed}++ if $args{stats};
210- return $event;
211+ return $event || $self->{null_event};
212 }
213
214 sub _packet_from_server {
215
216=== modified file 'lib/Processlist.pm'
217--- lib/Processlist.pm 2013-01-03 00:19:16 +0000
218+++ lib/Processlist.pm 2013-04-16 16:03:28 +0000
219@@ -245,14 +245,28 @@
220 $new_query = 1;
221 }
222 elsif ( $curr->[INFO] && defined $curr->[TIME]
223- && $query_start - $etime - $prev->[START] > $fudge ) {
224+ && $query_start - $etime - $prev->[START] > $fudge)
225+ {
226 # If the query's recalculated start time minus its previously
227 # calculated start time is greater than the fudge factor, then
228 # the query has restarted. I.e. the new start time is after
229 # the previous start time.
230- PTDEBUG && _d('Query restarted; new query',
231- $query_start, $etime, $prev->[START], $fudge);
232- $new_query = 1;
233+ my $ms = $self->{MasterSlave};
234+
235+ my $is_repl_thread = $ms->is_replication_thread({
236+ Command => $curr->[COMMAND],
237+ User => $curr->[USER],
238+ State => $curr->[STATE],
239+ Id => $curr->[ID]});
240+ if ( $is_repl_thread ) {
241+ PTDEBUG &&
242+ _d(q{Query has restarted but it's a replication thread, ignoring});
243+ }
244+ else {
245+ PTDEBUG && _d('Query restarted; new query',
246+ $query_start, $etime, $prev->[START], $fudge);
247+ $new_query = 1;
248+ }
249 }
250
251 if ( $new_query ) {
252
253=== modified file 't/lib/Processlist.t'
254--- t/lib/Processlist.t 2012-08-02 21:34:39 +0000
255+++ t/lib/Processlist.t 2013-04-16 16:03:28 +0000
256@@ -335,9 +335,116 @@
257 "New query2_2 is active, starting at 05:08"
258 );
259
260+
261+# ###########################################################################
262+# pt-query-digest --processlist: Duplicate entries for replication thread
263+# https://bugs.launchpad.net/percona-toolkit/+bug/1156901
264+# ###########################################################################
265+
266+# This is basically the same thing as above, but we're pretending to
267+# be a repl thread, so it should behave differently.
268+
269+$pl = Processlist->new(MasterSlave=>$ms);
270+
271+parse_n_times(
272+ 1,
273+ code => sub {
274+ return [
275+ [ 2, 'system user', 'localhost', 'test', 'Query', 0, 'executing', 'query2_2'],
276+ ],
277+ },
278+ time => Transformers::unix_timestamp('2001-01-01 00:05:03'),
279+ etime => 3.14159,
280+);
281+
282+is_deeply(
283+ $pl->_get_active_cxn(),
284+ {
285+ 2 => [
286+ 2, 'system user', 'localhost', 'test', 'Query', 0, 'executing', 'query2_2',
287+ Transformers::unix_timestamp('2001-01-01 00:05:03'), # START
288+ 3.14159, # ETIME
289+ Transformers::unix_timestamp('2001-01-01 00:05:03'), # FSEEN
290+ { executing => 0 },
291+ ],
292+ },
293+ 'query2_2 just started',
294+);
295+
296+# And there is no event on cxn 2.
297+is(
298+ scalar @events,
299+ 0,
300+ 'query2_2 has not fired yet',
301+);
302+
303+parse_n_times(
304+ 1,
305+ code => sub {
306+ return [
307+ [ 2, 'system user', 'localhost', 'test', 'Query', 0, 'executing', 'query2_2'],
308+ ],
309+ },
310+ time => Transformers::unix_timestamp('2001-01-01 00:05:05'),
311+ etime => 2.718,
312+);
313+
314+is(
315+ scalar @events,
316+ 0,
317+ 'query2_2 has not fired yet, same as with normal queries',
318+);
319+
320+is_deeply(
321+ $pl->_get_active_cxn(),
322+ {
323+ 2 => [
324+ 2, 'system user', 'localhost', 'test', 'Query', 0, 'executing', 'query2_2',
325+ Transformers::unix_timestamp('2001-01-01 00:05:03'),
326+ 3.14159,
327+ Transformers::unix_timestamp('2001-01-01 00:05:03'),
328+ { executing => 2 },
329+ ],
330+ },
331+ 'Cxn 2 still active with query starting at 05:03',
332+);
333+
334+# Same as above but five seconds and a half later
335+parse_n_times(
336+ 1,
337+ code => sub {
338+ return [
339+ [ 2, 'system user', 'localhost', 'test', 'Query', 0, 'executing', 'query2_2'],
340+ ],
341+ },
342+ time => Transformers::unix_timestamp('2001-01-01 00:05:08.500'),
343+ etime => 0.123,
344+);
345+
346+is_deeply(
347+ \@events,
348+ [],
349+ 'Original query2_2 not fired because we are a repl thrad',
350+);
351+
352+is_deeply(
353+ $pl->_get_active_cxn(),
354+ {
355+ 2 => [
356+ 2, 'system user', 'localhost', 'test', 'Query', 0, 'executing', 'query2_2',
357+ Transformers::unix_timestamp('2001-01-01 00:05:03'), # START
358+ 3.14159, # ETIME
359+ Transformers::unix_timestamp('2001-01-01 00:05:03'), # FSEEN
360+ { executing => 5.5 },
361+ ],
362+ },
363+ "Old query2_2 is active because we're a repl thread, but executing has updated"
364+);
365+
366 # ###########################################################################
367 # Issue 867: Make mk-query-digest detect Lock_time from processlist
368 # ###########################################################################
369+$ms = new MasterSlave(OptionParser=>1,DSNParser=>1,Quoter=>1);
370 $pl = Processlist->new(MasterSlave=>$ms);
371
372 # For 2/10ths of a second, the query is Locked. First time we see this

Subscribers

People subscribed via source and target branches