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

Merge lp:~percona-toolkit-dev/percona-toolkit/Percona-5.6-slow-query-log-Thead_id-becomes-Id-1299387 into lp:~percona-toolkit-dev/percona-toolkit/release-2.2.10

  1. Percona-5.6-slow-query-log-Thead_id-becomes-Id-1299387
  2. Merge into release-2.2.10
Proposed by Frank Cizmich
Status: Merged
Approved by: Daniel Nichter
Approved revision: 620
Merged at revision: 609
Proposed branch: lp:~percona-toolkit-dev/percona-toolkit/Percona-5.6-slow-query-log-Thead_id-becomes-Id-1299387
Merge into: lp:~percona-toolkit-dev/percona-toolkit/release-2.2.10
Diff against target: 484 lines (+200/-49)
9 files modified
bin/pt-index-usage (+23/-9)
bin/pt-query-digest (+12/-6)
bin/pt-table-usage (+41/-16)
bin/pt-upgrade (+23/-9)
lib/SlowLogParser.pm (+14/-6)
t/lib/SlowLogParser.t (+64/-0)
t/lib/samples/slowlogs/slow060.txt (+10/-0)
t/lib/samples/slowlogs/slow061.txt (+10/-0)
t/pt-query-digest/since_until.t (+3/-3)
To merge this branch: bzr merge lp:~percona-toolkit-dev/percona-toolkit/Percona-5.6-slow-query-log-Thead_id-becomes-Id-1299387
Reviewer Review Type Date Requested Status
Daniel Nichter Approve
Review via email: mp+228730@code.launchpad.net

Description of the change

PS 5.5 slow log has an independent row named "Thread_id"
MySQL 5.5 has none
MySQL 5.6 included this info at the end of the User@Host line as "Id"
PS 5.6 followed suit and dropped Thread_Id

This fix accommodates this and is backwards compatible with PS 5.5

Affects SlowLogParser and all tools included by it.

To post a comment you must log in.
Revision history for this message
Daniel Nichter (daniel-nichter) wrote :

There seems to be a mix of changes here? Maybe SlowLogParser.pm needs to be updated again in the tools?

review: Needs Fixing
lp:~percona-toolkit-dev/percona-toolkit/Percona-5.6-slow-query-log-Thead_id-becomes-Id-1299387 updated
620. By Frank Cizmich

Simplified code. Verified SlowLogParser module is correctly in sync with tools. Renamed test slow log files.

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-index-usage'
2--- bin/pt-index-usage 2014-07-04 17:16:08 +0000
3+++ bin/pt-index-usage 2014-07-30 20:28:34 +0000
4@@ -2772,12 +2772,13 @@
5 my ( $class ) = @_;
6 my $self = {
7 pending => [],
8+ last_event_offset => undef,
9 };
10 return bless $self, $class;
11 }
12
13 my $slow_log_ts_line = qr/^# Time: ([0-9: ]{15})/;
14-my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]/;
15+my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]\s*(?:Id:\s*(\d+))?/;
16 my $slow_log_hd_line = qr{
17 ^(?:
18 T[cC][pP]\s[pP]ort:\s+\d+ # case differs on windows/unix
19@@ -2808,6 +2809,7 @@
20 or defined($stmt = $next_event->())
21 ) {
22 my @properties = ('cmd', 'Query', 'pos_in_log', $pos_in_log);
23+ $self->{last_event_offset} = $pos_in_log;
24 $pos_in_log = $tell->();
25
26 if ( $stmt =~ s/$slow_log_hd_line//go ){ # Throw away header lines in log
27@@ -2840,19 +2842,25 @@
28 push @properties, 'ts', $time;
29 ++$got_ts;
30 if ( !$got_uh
31- && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
32+ && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
33 ) {
34 PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
35 push @properties, 'user', $user, 'host', $host, 'ip', $ip;
36- ++$got_uh;
37+ if ( $thread_id ) {
38+ push @properties, 'Thread_id', $thread_id;
39+ }
40+ ++$got_uh;
41 }
42 }
43
44 elsif ( !$got_uh
45- && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
46+ && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
47 ) {
48- PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
49- push @properties, 'user', $user, 'host', $host, 'ip', $ip;
50+ PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
51+ push @properties, 'user', $user, 'host', $host, 'ip', $ip;
52+ if ( $thread_id ) {
53+ push @properties, 'Thread_id', $thread_id;
54+ }
55 ++$got_uh;
56 }
57
58@@ -2933,9 +2941,15 @@
59
60 PTDEBUG && _d('Properties of event:', Dumper(\@properties));
61 my $event = { @properties };
62- if ( $args{stats} ) {
63- $args{stats}->{events_read}++;
64- $args{stats}->{events_parsed}++;
65+ if ( !$event->{arg} ) {
66+ PTDEBUG && _d('Partial event, no arg');
67+ }
68+ else {
69+ $self->{last_event_offset} = undef;
70+ if ( $args{stats} ) {
71+ $args{stats}->{events_read}++;
72+ $args{stats}->{events_parsed}++;
73+ }
74 }
75 return $event;
76 } # EVENT
77
78=== modified file 'bin/pt-query-digest'
79--- bin/pt-query-digest 2014-07-04 17:16:08 +0000
80+++ bin/pt-query-digest 2014-07-30 20:28:34 +0000
81@@ -4972,7 +4972,7 @@
82 }
83
84 my $slow_log_ts_line = qr/^# Time: ([0-9: ]{15})/;
85-my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]/;
86+my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]\s*(?:Id:\s*(\d+))?/;
87 my $slow_log_hd_line = qr{
88 ^(?:
89 T[cC][pP]\s[pP]ort:\s+\d+ # case differs on windows/unix
90@@ -5036,19 +5036,25 @@
91 push @properties, 'ts', $time;
92 ++$got_ts;
93 if ( !$got_uh
94- && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
95+ && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
96 ) {
97 PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
98 push @properties, 'user', $user, 'host', $host, 'ip', $ip;
99- ++$got_uh;
100+ if ( $thread_id ) {
101+ push @properties, 'Thread_id', $thread_id;
102+ }
103+ ++$got_uh;
104 }
105 }
106
107 elsif ( !$got_uh
108- && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
109+ && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
110 ) {
111- PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
112- push @properties, 'user', $user, 'host', $host, 'ip', $ip;
113+ PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
114+ push @properties, 'user', $user, 'host', $host, 'ip', $ip;
115+ if ( $thread_id ) {
116+ push @properties, 'Thread_id', $thread_id;
117+ }
118 ++$got_uh;
119 }
120
121
122=== modified file 'bin/pt-table-usage'
123--- bin/pt-table-usage 2014-07-04 17:16:08 +0000
124+++ bin/pt-table-usage 2014-07-30 20:28:34 +0000
125@@ -1556,12 +1556,13 @@
126 my ( $class ) = @_;
127 my $self = {
128 pending => [],
129+ last_event_offset => undef,
130 };
131 return bless $self, $class;
132 }
133
134 my $slow_log_ts_line = qr/^# Time: ([0-9: ]{15})/;
135-my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]/;
136+my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]\s*(?:Id:\s*(\d+))?/;
137 my $slow_log_hd_line = qr{
138 ^(?:
139 T[cC][pP]\s[pP]ort:\s+\d+ # case differs on windows/unix
140@@ -1592,6 +1593,7 @@
141 or defined($stmt = $next_event->())
142 ) {
143 my @properties = ('cmd', 'Query', 'pos_in_log', $pos_in_log);
144+ $self->{last_event_offset} = $pos_in_log;
145 $pos_in_log = $tell->();
146
147 if ( $stmt =~ s/$slow_log_hd_line//go ){ # Throw away header lines in log
148@@ -1624,19 +1626,25 @@
149 push @properties, 'ts', $time;
150 ++$got_ts;
151 if ( !$got_uh
152- && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
153+ && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
154 ) {
155 PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
156 push @properties, 'user', $user, 'host', $host, 'ip', $ip;
157- ++$got_uh;
158+ if ( $thread_id ) {
159+ push @properties, 'Thread_id', $thread_id;
160+ }
161+ ++$got_uh;
162 }
163 }
164
165 elsif ( !$got_uh
166- && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
167+ && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
168 ) {
169- PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
170- push @properties, 'user', $user, 'host', $host, 'ip', $ip;
171+ PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
172+ push @properties, 'user', $user, 'host', $host, 'ip', $ip;
173+ if ( $thread_id ) {
174+ push @properties, 'Thread_id', $thread_id;
175+ }
176 ++$got_uh;
177 }
178
179@@ -1676,14 +1684,25 @@
180
181 if ( !$found_arg && $pos == $len ) {
182 PTDEBUG && _d("Did not find arg, looking for special cases");
183- local $INPUT_RECORD_SEPARATOR = ";\n";
184+ local $INPUT_RECORD_SEPARATOR = ";\n"; # get next line
185 if ( defined(my $l = $next_event->()) ) {
186- chomp $l;
187- $l =~ s/^\s+//;
188- PTDEBUG && _d("Found admin statement", $l);
189- push @properties, 'cmd', 'Admin', 'arg', $l;
190- push @properties, 'bytes', length($properties[-1]);
191- $found_arg++;
192+ if ( $l =~ /^\s*[A-Z][a-z_]+: / ) {
193+ PTDEBUG && _d("Found NULL query before", $l);
194+ local $INPUT_RECORD_SEPARATOR = ";\n#";
195+ my $rest_of_event = $next_event->();
196+ push @{$self->{pending}}, $l . $rest_of_event;
197+ push @properties, 'cmd', 'Query', 'arg', '/* No query */';
198+ push @properties, 'bytes', 0;
199+ $found_arg++;
200+ }
201+ else {
202+ chomp $l;
203+ $l =~ s/^\s+//;
204+ PTDEBUG && _d("Found admin statement", $l);
205+ push @properties, 'cmd', 'Admin', 'arg', $l;
206+ push @properties, 'bytes', length($properties[-1]);
207+ $found_arg++;
208+ }
209 }
210 else {
211 PTDEBUG && _d("I can't figure out what to do with this line");
212@@ -1706,9 +1725,15 @@
213
214 PTDEBUG && _d('Properties of event:', Dumper(\@properties));
215 my $event = { @properties };
216- if ( $args{stats} ) {
217- $args{stats}->{events_read}++;
218- $args{stats}->{events_parsed}++;
219+ if ( !$event->{arg} ) {
220+ PTDEBUG && _d('Partial event, no arg');
221+ }
222+ else {
223+ $self->{last_event_offset} = undef;
224+ if ( $args{stats} ) {
225+ $args{stats}->{events_read}++;
226+ $args{stats}->{events_parsed}++;
227+ }
228 }
229 return $event;
230 } # EVENT
231
232=== modified file 'bin/pt-upgrade'
233--- bin/pt-upgrade 2014-07-04 17:16:08 +0000
234+++ bin/pt-upgrade 2014-07-30 20:28:34 +0000
235@@ -6537,12 +6537,13 @@
236 my ( $class ) = @_;
237 my $self = {
238 pending => [],
239+ last_event_offset => undef,
240 };
241 return bless $self, $class;
242 }
243
244 my $slow_log_ts_line = qr/^# Time: ([0-9: ]{15})/;
245-my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]/;
246+my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]\s*(?:Id:\s*(\d+))?/;
247 my $slow_log_hd_line = qr{
248 ^(?:
249 T[cC][pP]\s[pP]ort:\s+\d+ # case differs on windows/unix
250@@ -6573,6 +6574,7 @@
251 or defined($stmt = $next_event->())
252 ) {
253 my @properties = ('cmd', 'Query', 'pos_in_log', $pos_in_log);
254+ $self->{last_event_offset} = $pos_in_log;
255 $pos_in_log = $tell->();
256
257 if ( $stmt =~ s/$slow_log_hd_line//go ){ # Throw away header lines in log
258@@ -6605,19 +6607,25 @@
259 push @properties, 'ts', $time;
260 ++$got_ts;
261 if ( !$got_uh
262- && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
263+ && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
264 ) {
265 PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
266 push @properties, 'user', $user, 'host', $host, 'ip', $ip;
267- ++$got_uh;
268+ if ( $thread_id ) {
269+ push @properties, 'Thread_id', $thread_id;
270+ }
271+ ++$got_uh;
272 }
273 }
274
275 elsif ( !$got_uh
276- && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
277+ && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
278 ) {
279- PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
280- push @properties, 'user', $user, 'host', $host, 'ip', $ip;
281+ PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
282+ push @properties, 'user', $user, 'host', $host, 'ip', $ip;
283+ if ( $thread_id ) {
284+ push @properties, 'Thread_id', $thread_id;
285+ }
286 ++$got_uh;
287 }
288
289@@ -6698,9 +6706,15 @@
290
291 PTDEBUG && _d('Properties of event:', Dumper(\@properties));
292 my $event = { @properties };
293- if ( $args{stats} ) {
294- $args{stats}->{events_read}++;
295- $args{stats}->{events_parsed}++;
296+ if ( !$event->{arg} ) {
297+ PTDEBUG && _d('Partial event, no arg');
298+ }
299+ else {
300+ $self->{last_event_offset} = undef;
301+ if ( $args{stats} ) {
302+ $args{stats}->{events_read}++;
303+ $args{stats}->{events_parsed}++;
304+ }
305 }
306 return $event;
307 } # EVENT
308
309=== modified file 'lib/SlowLogParser.pm'
310--- lib/SlowLogParser.pm 2013-05-08 03:19:37 +0000
311+++ lib/SlowLogParser.pm 2014-07-30 20:28:34 +0000
312@@ -42,7 +42,7 @@
313 }
314
315 my $slow_log_ts_line = qr/^# Time: ([0-9: ]{15})/;
316-my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]/;
317+my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]\s*(?:Id:\s*(\d+))?/;
318 # These can appear in the log file when it's opened -- for example, when someone
319 # runs FLUSH LOGS or the server starts.
320 # /usr/sbin/mysqld, Version: 5.0.67-0ubuntu6-log ((Ubuntu)). started with:
321@@ -159,21 +159,29 @@
322 ++$got_ts;
323 # The User@Host might be concatenated onto the end of the Time.
324 if ( !$got_uh
325- && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
326+ && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
327 ) {
328 PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
329 push @properties, 'user', $user, 'host', $host, 'ip', $ip;
330- ++$got_uh;
331+ # 5.6 has the thread id on the User@Host line
332+ if ( $thread_id ) {
333+ push @properties, 'Thread_id', $thread_id;
334+ }
335+ ++$got_uh;
336 }
337 }
338
339 # Maybe it's the user/host line of a slow query log
340 # # User@Host: root[root] @ localhost []
341 elsif ( !$got_uh
342- && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
343+ && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
344 ) {
345- PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
346- push @properties, 'user', $user, 'host', $host, 'ip', $ip;
347+ PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
348+ push @properties, 'user', $user, 'host', $host, 'ip', $ip;
349+ # 5.6 has the thread id on the User@Host line
350+ if ( $thread_id ) {
351+ push @properties, 'Thread_id', $thread_id;
352+ }
353 ++$got_uh;
354 }
355
356
357=== modified file 't/lib/SlowLogParser.t'
358--- t/lib/SlowLogParser.t 2012-12-11 01:07:36 +0000
359+++ t/lib/SlowLogParser.t 2014-07-30 20:28:34 +0000
360@@ -1349,6 +1349,70 @@
361 ],
362 );
363
364+
365+# #############################################################################
366+# pt-query-digest fails to parse Thread_id on 5.6
367+# https://bugs.launchpad.net/percona-toolkit/+bug/1299387
368+# #############################################################################
369+
370+# first test with a Percona 5.5 slow log (includes an explicit Thread_id line)
371+# (MySQL 5.5 doesn't include thread id)
372+test_log_parser(
373+ parser => $p,
374+ file => "$sample/slow060.txt",
375+ result => [
376+ {
377+ Thread_id => '1', # here's our item
378+ Bytes_sent => '64',
379+ Killed => '0',
380+ Last_errno => '0',
381+ Lock_time => '0.000000',
382+ Query_time => '10.000373',
383+ Rows_affected => '0',
384+ Rows_examined => '0',
385+ Rows_read => '0',
386+ Rows_sent => '1',
387+ arg => 'select sleep(10)',
388+ bytes => 16,
389+ cmd => 'Query',
390+ host => 'localhost',
391+ ip => '127.0.0.1',
392+ pos_in_log => 0,
393+ timestamp => '1405358212',
394+ ts => '140714 14:16:52',
395+ user => 'root'
396+ },
397+ ],
398+);
399+
400+# now test with a Percona 5.6 slow log. Thread_id is now on the user@host line, and is called 'Id'.
401+# (this is in line with MySQL 5.6)
402+test_log_parser(
403+ parser => $p,
404+ file => "$sample/slow061.txt",
405+ result => [
406+ {
407+ Thread_id => 1, # here's our item
408+ Bytes_sent => '64',
409+ Lock_time => '0.000000',
410+ Query_time => '11.013723',
411+ Rows_affected => '0',
412+ Rows_examined => '0',
413+ Rows_sent => '1',
414+ arg => 'select sleep(11)',
415+ bytes => 16,
416+ cmd => 'Query',
417+ host => 'localhost',
418+ ip => '127.0.0.1',
419+ pos_in_log => 0,
420+ timestamp => '1405360304',
421+ ts => '140714 14:51:44',
422+ user => 'root',
423+ },
424+ ],
425+);
426+
427+
428 # #############################################################################
429 # Done.
430 # #############################################################################
431
432=== added file 't/lib/samples/slowlogs/slow060.txt'
433--- t/lib/samples/slowlogs/slow060.txt 1970-01-01 00:00:00 +0000
434+++ t/lib/samples/slowlogs/slow060.txt 2014-07-30 20:28:34 +0000
435@@ -0,0 +1,10 @@
436+bin/mysqld, Version: 5.5.38-35.2-log (Percona Server (GPL), Release 35.2, Revision 674). started with:
437+Tcp port: 3306 Unix socket: (null)
438+Time Id Command Argument
439+# Time: 140714 14:16:52
440+# User@Host: root[root] @ localhost [127.0.0.1]
441+# Thread_id: 1 Schema: Last_errno: 0 Killed: 0
442+# Query_time: 10.000373 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 0
443+# Bytes_sent: 64
444+SET timestamp=1405358212;
445+select sleep(10);
446
447=== added file 't/lib/samples/slowlogs/slow061.txt'
448--- t/lib/samples/slowlogs/slow061.txt 1970-01-01 00:00:00 +0000
449+++ t/lib/samples/slowlogs/slow061.txt 2014-07-30 20:28:34 +0000
450@@ -0,0 +1,10 @@
451+bin/mysqld, Version: 5.6.19-67.0-log (Percona Server (GPL), Release 67.0, Revision 618). started with:
452+Tcp port: 3306 Unix socket: (null)
453+Time Id Command Argument
454+# Time: 140714 14:51:44
455+# User@Host: root[root] @ localhost [127.0.0.1] Id: 1
456+# Schema: Last_errno: 0 Killed: 0
457+# Query_time: 11.013723 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0
458+# Bytes_sent: 64
459+SET timestamp=1405360304;
460+select sleep(11);
461
462=== modified file 't/pt-query-digest/since_until.t'
463--- t/pt-query-digest/since_until.t 2013-03-05 16:59:33 +0000
464+++ t/pt-query-digest/since_until.t 2014-07-30 20:28:34 +0000
465@@ -52,16 +52,16 @@
466 '--since 090727'
467 );
468
469-# This test will fail come July 2014.
470+# This test will fail come July 2015.
471 ok(
472 no_diff(
473 sub { pt_query_digest::main(@args,
474- "$sample_in/slow033.txt", qw(--since 1825d),
475+ "$sample_in/slow033.txt", qw(--since 2190d),
476 )},
477 "t/pt-query-digest/samples/slow033-since-Nd.txt",
478 stderr => 1,
479 ),
480- '--since 1825d (5 years ago)'
481+ '--since 2190d (6 years ago)'
482 );
483
484 # --until

Subscribers

People subscribed via source and target branches

to all changes: