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

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

  1. fix-slowlog-ts-bug-1082599
  2. Merge into 2.1
Proposed by Daniel Nichter
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
Review via email: mp+139129@code.launchpad.net
To post a comment you must log in.
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
=== modified file 'bin/pt-query-digest'
--- bin/pt-query-digest 2012-12-10 23:41:11 +0000
+++ bin/pt-query-digest 2012-12-11 01:40:25 +0000
@@ -4875,14 +4875,25 @@
48754875
4876 if ( !$found_arg && $pos == $len ) {4876 if ( !$found_arg && $pos == $len ) {
4877 PTDEBUG && _d("Did not find arg, looking for special cases");4877 PTDEBUG && _d("Did not find arg, looking for special cases");
4878 local $INPUT_RECORD_SEPARATOR = ";\n";4878 local $INPUT_RECORD_SEPARATOR = ";\n"; # get next line
4879 if ( defined(my $l = $next_event->()) ) {4879 if ( defined(my $l = $next_event->()) ) {
4880 chomp $l;4880 if ( $l =~ /^\s*[A-Z][a-z_]+: / ) {
4881 $l =~ s/^\s+//;4881 PTDEBUG && _d("Found NULL query before", $l);
4882 PTDEBUG && _d("Found admin statement", $l);4882 local $INPUT_RECORD_SEPARATOR = ";\n#";
4883 push @properties, 'cmd', 'Admin', 'arg', $l;4883 my $rest_of_event = $next_event->();
4884 push @properties, 'bytes', length($properties[-1]);4884 push @{$self->{pending}}, $l . $rest_of_event;
4885 $found_arg++;4885 push @properties, 'cmd', 'Query', 'arg', '/* No query */';
4886 push @properties, 'bytes', 0;
4887 $found_arg++;
4888 }
4889 else {
4890 chomp $l;
4891 $l =~ s/^\s+//;
4892 PTDEBUG && _d("Found admin statement", $l);
4893 push @properties, 'cmd', 'Admin', 'arg', $l;
4894 push @properties, 'bytes', length($properties[-1]);
4895 $found_arg++;
4896 }
4886 }4897 }
4887 else {4898 else {
4888 PTDEBUG && _d("I can't figure out what to do with this line");4899 PTDEBUG && _d("I can't figure out what to do with this line");
48894900
=== modified file 'lib/SlowLogParser.pm'
--- lib/SlowLogParser.pm 2012-01-19 19:46:56 +0000
+++ lib/SlowLogParser.pm 2012-12-11 01:40:25 +0000
@@ -235,14 +235,35 @@
235 # this only if we've seen the user/host line.235 # this only if we've seen the user/host line.
236 if ( !$found_arg && $pos == $len ) {236 if ( !$found_arg && $pos == $len ) {
237 PTDEBUG && _d("Did not find arg, looking for special cases");237 PTDEBUG && _d("Did not find arg, looking for special cases");
238 local $INPUT_RECORD_SEPARATOR = ";\n";238 local $INPUT_RECORD_SEPARATOR = ";\n"; # get next line
239 if ( defined(my $l = $next_event->()) ) {239 if ( defined(my $l = $next_event->()) ) {
240 chomp $l;240 if ( $l =~ /^\s*[A-Z][a-z_]+: / ) {
241 $l =~ s/^\s+//;241 PTDEBUG && _d("Found NULL query before", $l);
242 PTDEBUG && _d("Found admin statement", $l);242 # https://bugs.launchpad.net/percona-toolkit/+bug/1082599
243 push @properties, 'cmd', 'Admin', 'arg', $l;243 # This is really pathological but it happens:
244 push @properties, 'bytes', length($properties[-1]);244 # header_for_query_1
245 $found_arg++;245 # SET timestamp=123;
246 # use db;
247 # header_for_query_2
248 # In this case, "get next line" ^ will actually fetch
249 # header_for_query_2 and the first line of any arg data,
250 # so to get the rest of the arg data, we switch back to
251 # the default input rec. sep.
252 local $INPUT_RECORD_SEPARATOR = ";\n#";
253 my $rest_of_event = $next_event->();
254 push @{$self->{pending}}, $l . $rest_of_event;
255 push @properties, 'cmd', 'Query', 'arg', '/* No query */';
256 push @properties, 'bytes', 0;
257 $found_arg++;
258 }
259 else {
260 chomp $l;
261 $l =~ s/^\s+//;
262 PTDEBUG && _d("Found admin statement", $l);
263 push @properties, 'cmd', 'Admin', 'arg', $l;
264 push @properties, 'bytes', length($properties[-1]);
265 $found_arg++;
266 }
246 }267 }
247 else {268 else {
248 # Unrecoverable -- who knows what happened. This is possible,269 # Unrecoverable -- who knows what happened. This is possible,
249270
=== modified file 't/lib/SlowLogParser.t'
--- t/lib/SlowLogParser.t 2012-03-30 02:16:53 +0000
+++ t/lib/SlowLogParser.t 2012-12-11 01:40:25 +0000
@@ -9,8 +9,8 @@
9use strict;9use strict;
10use warnings FATAL => 'all';10use warnings FATAL => 'all';
11use English qw(-no_match_vars);11use English qw(-no_match_vars);
12use Test::More tests => 48;
1312
13use Test::More;
14use SlowLogParser;14use SlowLogParser;
15use PerconaTest;15use PerconaTest;
1616
@@ -1297,6 +1297,59 @@
1297);1297);
12981298
1299# #############################################################################1299# #############################################################################
1300# pt-query-digest fails to parse timestamp with no query
1301# https://bugs.launchpad.net/percona-toolkit/+bug/1082599
1302# #############################################################################
1303test_log_parser(
1304 parser => $p,
1305 file => "$sample/slow056.txt",
1306 result => [
1307 { Lock_time => '0.000000',
1308 Query_time => '0.000102',
1309 Rows_read => '0',
1310 Rows_affected => '0',
1311 Rows_examined => '0',
1312 Rows_sent => '0',
1313 arg => '/* No query */',
1314 bytes => '0',
1315 cmd => 'Query',
1316 pos_in_log => '0',
1317 ts => '121123 19:56:06',
1318 Thread_id => '558038',
1319 Last_errno => 0,
1320 Killed => 0,
1321 db => 'test_db',
1322 host => '',
1323 Schema => 'test_db',
1324 ip => '127.0.0.1',
1325 timestamp => '1111111111',
1326 user => 'root',
1327 },
1328 {
1329 ts => '121123 19:56:06',
1330 Killed => '0',
1331 Last_errno => '0',
1332 Lock_time => '0.000197',
1333 Query_time => '0.002515',
1334 Rows_affected => '1',
1335 Rows_examined => '1',
1336 Rows_read => '0',
1337 Rows_sent => '0',
1338 Schema => 'test_db',
1339 Thread_id => '558032',
1340 arg => 'update t set b = b + 30 where user_id=1',
1341 bytes => 39,
1342 cmd => 'Query',
1343 host => '',
1344 ip => '127.0.0.1',
1345 pos_in_log => 596,
1346 timestamp => '2222222222',
1347 user => 'root',
1348 },
1349 ],
1350);
1351
1352# #############################################################################
1300# Done.1353# Done.
1301# #############################################################################1354# #############################################################################
1302my $output = '';1355my $output = '';
@@ -1310,4 +1363,4 @@
1310 qr/Complete test coverage/,1363 qr/Complete test coverage/,
1311 '_d() works'1364 '_d() works'
1312);1365);
1313exit;1366done_testing;
13141367
=== added file 't/lib/samples/slowlogs/slow056.txt'
--- t/lib/samples/slowlogs/slow056.txt 1970-01-01 00:00:00 +0000
+++ t/lib/samples/slowlogs/slow056.txt 2012-12-11 01:40:25 +0000
@@ -0,0 +1,12 @@
1# Time: 121123 19:56:06.0000001967
2# User@Host: root[root] @ [127.0.0.1]
3# Thread_id: 558038 Schema: test_db Last_errno: 0 Killed: 0
4# Query_time: 0.000102 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0 Rows_read: 0
5SET timestamp=1111111111;
6use test_db;
7# Time: 121123 19:56:06.0000002134
8# User@Host: root[root] @ [127.0.0.1]
9# Thread_id: 558032 Schema: test_db Last_errno: 0 Killed: 0
10# Query_time: 0.002515 Lock_time: 0.000197 Rows_sent: 0 Rows_examined: 1 Rows_affected: 1 Rows_read: 0
11SET timestamp=2222222222;
12update t set b = b + 30 where user_id=1;
013
=== added file 't/pt-query-digest/samples/slow056.txt'
--- t/pt-query-digest/samples/slow056.txt 1970-01-01 00:00:00 +0000
+++ t/pt-query-digest/samples/slow056.txt 2012-12-11 01:40:25 +0000
@@ -0,0 +1,68 @@
1
2# Query 1: 0 QPS, 0x concurrency, ID 0x54E0BB9E70EAA792 at byte 596 ______
3# This item is included in the report because it matches --limit.
4# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
5# Query_time sparkline: | ^ |
6# Time range: all events occurred at 2012-11-23 19:56:06
7# Attribute pct total min max avg 95% stddev median
8# ============ === ======= ======= ======= ======= ======= ======= =======
9# Count 50 1
10# Exec time 96 3ms 3ms 3ms 3ms 3ms 0 3ms
11# Lock time 100 197us 197us 197us 197us 197us 0 197us
12# Rows sent 0 0 0 0 0 0 0 0
13# Rows examine 100 1 1 1 1 1 0 1
14# Rows affecte 100 1 1 1 1 1 0 1
15# Rows read 0 0 0 0 0 0 0 0
16# Query size 100 39 39 39 39 39 0 39
17# String:
18# Databases test_db
19# Hosts
20# Last errno 0
21# Users root
22# Query_time distribution
23# 1us
24# 10us
25# 100us
26# 1ms ################################################################
27# 10ms
28# 100ms
29# 1s
30# 10s+
31# Tables
32# SHOW TABLE STATUS FROM `test_db` LIKE 't'\G
33# SHOW CREATE TABLE `test_db`.`t`\G
34update t set b = b + 30 where user_id=1\G
35# Converted for EXPLAIN
36# EXPLAIN /*!50100 PARTITIONS*/
37select b = b + 30 from t where user_id=1\G
38
39# Query 2: 0 QPS, 0x concurrency, ID 0xE9800998ECF8427E at byte 0 ________
40# This item is included in the report because it matches --limit.
41# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
42# Query_time sparkline: | ^ |
43# Time range: all events occurred at 2012-11-23 19:56:06
44# Attribute pct total min max avg 95% stddev median
45# ============ === ======= ======= ======= ======= ======= ======= =======
46# Count 50 1
47# Exec time 3 102us 102us 102us 102us 102us 0 102us
48# Lock time 0 0 0 0 0 0 0 0
49# Rows sent 0 0 0 0 0 0 0 0
50# Rows examine 0 0 0 0 0 0 0 0
51# Rows affecte 0 0 0 0 0 0 0 0
52# Rows read 0 0 0 0 0 0 0 0
53# Query size 0 0 0 0 0 0 0 0
54# String:
55# Databases test_db
56# Hosts
57# Last errno 0
58# Users root
59# Query_time distribution
60# 1us
61# 10us
62# 100us ################################################################
63# 1ms
64# 10ms
65# 100ms
66# 1s
67# 10s+
68/* No query */\G
069
=== modified file 't/pt-query-digest/slowlog_analyses.t'
--- t/pt-query-digest/slowlog_analyses.t 2012-11-21 16:58:40 +0000
+++ t/pt-query-digest/slowlog_analyses.t 2012-12-11 01:40:25 +0000
@@ -9,10 +9,9 @@
9use strict;9use strict;
10use warnings FATAL => 'all';10use warnings FATAL => 'all';
11use English qw(-no_match_vars);11use English qw(-no_match_vars);
12use Test::More tests => 44;12use Test::More;
1313
14use PerconaTest;14use PerconaTest;
15
16require "$trunk/bin/pt-query-digest";15require "$trunk/bin/pt-query-digest";
1716
18# #############################################################################17# #############################################################################
@@ -435,6 +434,17 @@
435);434);
436435
437# #############################################################################436# #############################################################################
437# Bug 1082599: pt-query-digest fails to parse timestamp with no query
438# #############################################################################
439ok(
440 no_diff(
441 sub { pt_query_digest::main(@args, $sample.'slow056.txt') },
442 "t/pt-query-digest/samples/slow056.txt",
443 ),
444 'Analysis for slow056 (no query bug 1082599)'
445);
446
447# #############################################################################
438# Done.448# Done.
439# #############################################################################449# #############################################################################
440exit;450done_testing;

Subscribers

People subscribed via source and target branches