Merge lp:~percona-toolkit-dev/percona-toolkit/fix-slowlog-ts-bug-1082599 into lp:percona-toolkit/2.1

Proposed by Daniel Nichter on 2012-12-11
Status: Merged
Merged at revision: 496
Proposed branch: lp:~percona-toolkit-dev/percona-toolkit/fix-slowlog-ts-bug-1082599
Merge into: lp:percona-toolkit/2.1
Diff against target: 288 lines (+194/-19)
6 files modified
bin/pt-query-digest (+18/-7)
lib/SlowLogParser.pm (+28/-7)
t/lib/SlowLogParser.t (+55/-2)
t/lib/samples/slowlogs/slow056.txt (+12/-0)
t/pt-query-digest/samples/slow056.txt (+68/-0)
t/pt-query-digest/slowlog_analyses.t (+13/-3)
To merge this branch: bzr merge lp:~percona-toolkit-dev/percona-toolkit/fix-slowlog-ts-bug-1082599
Reviewer Review Type Date Requested Status
Daniel Nichter Approve on 2012-12-11
Review via email: mp+139129@code.launchpad.net
To post a comment you must log in.
review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'bin/pt-query-digest'
2--- bin/pt-query-digest 2012-12-10 23:41:11 +0000
3+++ bin/pt-query-digest 2012-12-11 01:40:25 +0000
4@@ -4875,14 +4875,25 @@
5
6 if ( !$found_arg && $pos == $len ) {
7 PTDEBUG && _d("Did not find arg, looking for special cases");
8- local $INPUT_RECORD_SEPARATOR = ";\n";
9+ local $INPUT_RECORD_SEPARATOR = ";\n"; # get next line
10 if ( defined(my $l = $next_event->()) ) {
11- chomp $l;
12- $l =~ s/^\s+//;
13- PTDEBUG && _d("Found admin statement", $l);
14- push @properties, 'cmd', 'Admin', 'arg', $l;
15- push @properties, 'bytes', length($properties[-1]);
16- $found_arg++;
17+ if ( $l =~ /^\s*[A-Z][a-z_]+: / ) {
18+ PTDEBUG && _d("Found NULL query before", $l);
19+ local $INPUT_RECORD_SEPARATOR = ";\n#";
20+ my $rest_of_event = $next_event->();
21+ push @{$self->{pending}}, $l . $rest_of_event;
22+ push @properties, 'cmd', 'Query', 'arg', '/* No query */';
23+ push @properties, 'bytes', 0;
24+ $found_arg++;
25+ }
26+ else {
27+ chomp $l;
28+ $l =~ s/^\s+//;
29+ PTDEBUG && _d("Found admin statement", $l);
30+ push @properties, 'cmd', 'Admin', 'arg', $l;
31+ push @properties, 'bytes', length($properties[-1]);
32+ $found_arg++;
33+ }
34 }
35 else {
36 PTDEBUG && _d("I can't figure out what to do with this line");
37
38=== modified file 'lib/SlowLogParser.pm'
39--- lib/SlowLogParser.pm 2012-01-19 19:46:56 +0000
40+++ lib/SlowLogParser.pm 2012-12-11 01:40:25 +0000
41@@ -235,14 +235,35 @@
42 # this only if we've seen the user/host line.
43 if ( !$found_arg && $pos == $len ) {
44 PTDEBUG && _d("Did not find arg, looking for special cases");
45- local $INPUT_RECORD_SEPARATOR = ";\n";
46+ local $INPUT_RECORD_SEPARATOR = ";\n"; # get next line
47 if ( defined(my $l = $next_event->()) ) {
48- chomp $l;
49- $l =~ s/^\s+//;
50- PTDEBUG && _d("Found admin statement", $l);
51- push @properties, 'cmd', 'Admin', 'arg', $l;
52- push @properties, 'bytes', length($properties[-1]);
53- $found_arg++;
54+ if ( $l =~ /^\s*[A-Z][a-z_]+: / ) {
55+ PTDEBUG && _d("Found NULL query before", $l);
56+ # https://bugs.launchpad.net/percona-toolkit/+bug/1082599
57+ # This is really pathological but it happens:
58+ # header_for_query_1
59+ # SET timestamp=123;
60+ # use db;
61+ # header_for_query_2
62+ # In this case, "get next line" ^ will actually fetch
63+ # header_for_query_2 and the first line of any arg data,
64+ # so to get the rest of the arg data, we switch back to
65+ # the default input rec. sep.
66+ local $INPUT_RECORD_SEPARATOR = ";\n#";
67+ my $rest_of_event = $next_event->();
68+ push @{$self->{pending}}, $l . $rest_of_event;
69+ push @properties, 'cmd', 'Query', 'arg', '/* No query */';
70+ push @properties, 'bytes', 0;
71+ $found_arg++;
72+ }
73+ else {
74+ chomp $l;
75+ $l =~ s/^\s+//;
76+ PTDEBUG && _d("Found admin statement", $l);
77+ push @properties, 'cmd', 'Admin', 'arg', $l;
78+ push @properties, 'bytes', length($properties[-1]);
79+ $found_arg++;
80+ }
81 }
82 else {
83 # Unrecoverable -- who knows what happened. This is possible,
84
85=== modified file 't/lib/SlowLogParser.t'
86--- t/lib/SlowLogParser.t 2012-03-30 02:16:53 +0000
87+++ t/lib/SlowLogParser.t 2012-12-11 01:40:25 +0000
88@@ -9,8 +9,8 @@
89 use strict;
90 use warnings FATAL => 'all';
91 use English qw(-no_match_vars);
92-use Test::More tests => 48;
93
94+use Test::More;
95 use SlowLogParser;
96 use PerconaTest;
97
98@@ -1297,6 +1297,59 @@
99 );
100
101 # #############################################################################
102+# pt-query-digest fails to parse timestamp with no query
103+# https://bugs.launchpad.net/percona-toolkit/+bug/1082599
104+# #############################################################################
105+test_log_parser(
106+ parser => $p,
107+ file => "$sample/slow056.txt",
108+ result => [
109+ { Lock_time => '0.000000',
110+ Query_time => '0.000102',
111+ Rows_read => '0',
112+ Rows_affected => '0',
113+ Rows_examined => '0',
114+ Rows_sent => '0',
115+ arg => '/* No query */',
116+ bytes => '0',
117+ cmd => 'Query',
118+ pos_in_log => '0',
119+ ts => '121123 19:56:06',
120+ Thread_id => '558038',
121+ Last_errno => 0,
122+ Killed => 0,
123+ db => 'test_db',
124+ host => '',
125+ Schema => 'test_db',
126+ ip => '127.0.0.1',
127+ timestamp => '1111111111',
128+ user => 'root',
129+ },
130+ {
131+ ts => '121123 19:56:06',
132+ Killed => '0',
133+ Last_errno => '0',
134+ Lock_time => '0.000197',
135+ Query_time => '0.002515',
136+ Rows_affected => '1',
137+ Rows_examined => '1',
138+ Rows_read => '0',
139+ Rows_sent => '0',
140+ Schema => 'test_db',
141+ Thread_id => '558032',
142+ arg => 'update t set b = b + 30 where user_id=1',
143+ bytes => 39,
144+ cmd => 'Query',
145+ host => '',
146+ ip => '127.0.0.1',
147+ pos_in_log => 596,
148+ timestamp => '2222222222',
149+ user => 'root',
150+ },
151+ ],
152+);
153+
154+# #############################################################################
155 # Done.
156 # #############################################################################
157 my $output = '';
158@@ -1310,4 +1363,4 @@
159 qr/Complete test coverage/,
160 '_d() works'
161 );
162-exit;
163+done_testing;
164
165=== added file 't/lib/samples/slowlogs/slow056.txt'
166--- t/lib/samples/slowlogs/slow056.txt 1970-01-01 00:00:00 +0000
167+++ t/lib/samples/slowlogs/slow056.txt 2012-12-11 01:40:25 +0000
168@@ -0,0 +1,12 @@
169+# Time: 121123 19:56:06.0000001967
170+# User@Host: root[root] @ [127.0.0.1]
171+# Thread_id: 558038 Schema: test_db Last_errno: 0 Killed: 0
172+# Query_time: 0.000102 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0 Rows_read: 0
173+SET timestamp=1111111111;
174+use test_db;
175+# Time: 121123 19:56:06.0000002134
176+# User@Host: root[root] @ [127.0.0.1]
177+# Thread_id: 558032 Schema: test_db Last_errno: 0 Killed: 0
178+# Query_time: 0.002515 Lock_time: 0.000197 Rows_sent: 0 Rows_examined: 1 Rows_affected: 1 Rows_read: 0
179+SET timestamp=2222222222;
180+update t set b = b + 30 where user_id=1;
181
182=== added file 't/pt-query-digest/samples/slow056.txt'
183--- t/pt-query-digest/samples/slow056.txt 1970-01-01 00:00:00 +0000
184+++ t/pt-query-digest/samples/slow056.txt 2012-12-11 01:40:25 +0000
185@@ -0,0 +1,68 @@
186+
187+# Query 1: 0 QPS, 0x concurrency, ID 0x54E0BB9E70EAA792 at byte 596 ______
188+# This item is included in the report because it matches --limit.
189+# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
190+# Query_time sparkline: | ^ |
191+# Time range: all events occurred at 2012-11-23 19:56:06
192+# Attribute pct total min max avg 95% stddev median
193+# ============ === ======= ======= ======= ======= ======= ======= =======
194+# Count 50 1
195+# Exec time 96 3ms 3ms 3ms 3ms 3ms 0 3ms
196+# Lock time 100 197us 197us 197us 197us 197us 0 197us
197+# Rows sent 0 0 0 0 0 0 0 0
198+# Rows examine 100 1 1 1 1 1 0 1
199+# Rows affecte 100 1 1 1 1 1 0 1
200+# Rows read 0 0 0 0 0 0 0 0
201+# Query size 100 39 39 39 39 39 0 39
202+# String:
203+# Databases test_db
204+# Hosts
205+# Last errno 0
206+# Users root
207+# Query_time distribution
208+# 1us
209+# 10us
210+# 100us
211+# 1ms ################################################################
212+# 10ms
213+# 100ms
214+# 1s
215+# 10s+
216+# Tables
217+# SHOW TABLE STATUS FROM `test_db` LIKE 't'\G
218+# SHOW CREATE TABLE `test_db`.`t`\G
219+update t set b = b + 30 where user_id=1\G
220+# Converted for EXPLAIN
221+# EXPLAIN /*!50100 PARTITIONS*/
222+select b = b + 30 from t where user_id=1\G
223+
224+# Query 2: 0 QPS, 0x concurrency, ID 0xE9800998ECF8427E at byte 0 ________
225+# This item is included in the report because it matches --limit.
226+# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
227+# Query_time sparkline: | ^ |
228+# Time range: all events occurred at 2012-11-23 19:56:06
229+# Attribute pct total min max avg 95% stddev median
230+# ============ === ======= ======= ======= ======= ======= ======= =======
231+# Count 50 1
232+# Exec time 3 102us 102us 102us 102us 102us 0 102us
233+# Lock time 0 0 0 0 0 0 0 0
234+# Rows sent 0 0 0 0 0 0 0 0
235+# Rows examine 0 0 0 0 0 0 0 0
236+# Rows affecte 0 0 0 0 0 0 0 0
237+# Rows read 0 0 0 0 0 0 0 0
238+# Query size 0 0 0 0 0 0 0 0
239+# String:
240+# Databases test_db
241+# Hosts
242+# Last errno 0
243+# Users root
244+# Query_time distribution
245+# 1us
246+# 10us
247+# 100us ################################################################
248+# 1ms
249+# 10ms
250+# 100ms
251+# 1s
252+# 10s+
253+/* No query */\G
254
255=== modified file 't/pt-query-digest/slowlog_analyses.t'
256--- t/pt-query-digest/slowlog_analyses.t 2012-11-21 16:58:40 +0000
257+++ t/pt-query-digest/slowlog_analyses.t 2012-12-11 01:40:25 +0000
258@@ -9,10 +9,9 @@
259 use strict;
260 use warnings FATAL => 'all';
261 use English qw(-no_match_vars);
262-use Test::More tests => 44;
263+use Test::More;
264
265 use PerconaTest;
266-
267 require "$trunk/bin/pt-query-digest";
268
269 # #############################################################################
270@@ -435,6 +434,17 @@
271 );
272
273 # #############################################################################
274+# Bug 1082599: pt-query-digest fails to parse timestamp with no query
275+# #############################################################################
276+ok(
277+ no_diff(
278+ sub { pt_query_digest::main(@args, $sample.'slow056.txt') },
279+ "t/pt-query-digest/samples/slow056.txt",
280+ ),
281+ 'Analysis for slow056 (no query bug 1082599)'
282+);
283+
284+# #############################################################################
285 # Done.
286 # #############################################################################
287-exit;
288+done_testing;

Subscribers

People subscribed via source and target branches