diff --git a/bin/pt-query-digest b/bin/pt-query-digest index 36736753..9a511c5c 100755 --- a/bin/pt-query-digest +++ b/bin/pt-query-digest @@ -4875,14 +4875,25 @@ sub parse_event { if ( !$found_arg && $pos == $len ) { PTDEBUG && _d("Did not find arg, looking for special cases"); - local $INPUT_RECORD_SEPARATOR = ";\n"; + local $INPUT_RECORD_SEPARATOR = ";\n"; # get next line if ( defined(my $l = $next_event->()) ) { - chomp $l; - $l =~ s/^\s+//; - PTDEBUG && _d("Found admin statement", $l); - push @properties, 'cmd', 'Admin', 'arg', $l; - push @properties, 'bytes', length($properties[-1]); - $found_arg++; + if ( $l =~ /^\s*[A-Z][a-z_]+: / ) { + PTDEBUG && _d("Found NULL query before", $l); + local $INPUT_RECORD_SEPARATOR = ";\n#"; + my $rest_of_event = $next_event->(); + push @{$self->{pending}}, $l . $rest_of_event; + push @properties, 'cmd', 'Query', 'arg', '/* No query */'; + push @properties, 'bytes', 0; + $found_arg++; + } + else { + chomp $l; + $l =~ s/^\s+//; + PTDEBUG && _d("Found admin statement", $l); + push @properties, 'cmd', 'Admin', 'arg', $l; + push @properties, 'bytes', length($properties[-1]); + $found_arg++; + } } else { PTDEBUG && _d("I can't figure out what to do with this line"); diff --git a/lib/SlowLogParser.pm b/lib/SlowLogParser.pm index df88b53e..9840539c 100644 --- a/lib/SlowLogParser.pm +++ b/lib/SlowLogParser.pm @@ -235,14 +235,35 @@ sub parse_event { # this only if we've seen the user/host line. if ( !$found_arg && $pos == $len ) { PTDEBUG && _d("Did not find arg, looking for special cases"); - local $INPUT_RECORD_SEPARATOR = ";\n"; + local $INPUT_RECORD_SEPARATOR = ";\n"; # get next line if ( defined(my $l = $next_event->()) ) { - chomp $l; - $l =~ s/^\s+//; - PTDEBUG && _d("Found admin statement", $l); - push @properties, 'cmd', 'Admin', 'arg', $l; - push @properties, 'bytes', length($properties[-1]); - $found_arg++; + if ( $l =~ /^\s*[A-Z][a-z_]+: / ) { + PTDEBUG && _d("Found NULL query before", $l); + # https://bugs.launchpad.net/percona-toolkit/+bug/1082599 + # This is really pathological but it happens: + # header_for_query_1 + # SET timestamp=123; + # use db; + # header_for_query_2 + # In this case, "get next line" ^ will actually fetch + # header_for_query_2 and the first line of any arg data, + # so to get the rest of the arg data, we switch back to + # the default input rec. sep. + local $INPUT_RECORD_SEPARATOR = ";\n#"; + my $rest_of_event = $next_event->(); + push @{$self->{pending}}, $l . $rest_of_event; + push @properties, 'cmd', 'Query', 'arg', '/* No query */'; + push @properties, 'bytes', 0; + $found_arg++; + } + else { + chomp $l; + $l =~ s/^\s+//; + PTDEBUG && _d("Found admin statement", $l); + push @properties, 'cmd', 'Admin', 'arg', $l; + push @properties, 'bytes', length($properties[-1]); + $found_arg++; + } } else { # Unrecoverable -- who knows what happened. This is possible, diff --git a/t/lib/SlowLogParser.t b/t/lib/SlowLogParser.t index ca138f59..1fb5ec4d 100644 --- a/t/lib/SlowLogParser.t +++ b/t/lib/SlowLogParser.t @@ -9,8 +9,8 @@ BEGIN { use strict; use warnings FATAL => 'all'; use English qw(-no_match_vars); -use Test::More tests => 48; +use Test::More; use SlowLogParser; use PerconaTest; @@ -1296,6 +1296,59 @@ test_log_parser( ], ); +# ############################################################################# +# pt-query-digest fails to parse timestamp with no query +# https://bugs.launchpad.net/percona-toolkit/+bug/1082599 +# ############################################################################# +test_log_parser( + parser => $p, + file => "$sample/slow056.txt", + result => [ + { Lock_time => '0.000000', + Query_time => '0.000102', + Rows_read => '0', + Rows_affected => '0', + Rows_examined => '0', + Rows_sent => '0', + arg => '/* No query */', + bytes => '0', + cmd => 'Query', + pos_in_log => '0', + ts => '121123 19:56:06', + Thread_id => '558038', + Last_errno => 0, + Killed => 0, + db => 'test_db', + host => '', + Schema => 'test_db', + ip => '127.0.0.1', + timestamp => '1111111111', + user => 'root', + }, + { + ts => '121123 19:56:06', + Killed => '0', + Last_errno => '0', + Lock_time => '0.000197', + Query_time => '0.002515', + Rows_affected => '1', + Rows_examined => '1', + Rows_read => '0', + Rows_sent => '0', + Schema => 'test_db', + Thread_id => '558032', + arg => 'update t set b = b + 30 where user_id=1', + bytes => 39, + cmd => 'Query', + host => '', + ip => '127.0.0.1', + pos_in_log => 596, + timestamp => '2222222222', + user => 'root', + }, + ], +); + # ############################################################################# # Done. # ############################################################################# @@ -1310,4 +1363,4 @@ like( qr/Complete test coverage/, '_d() works' ); -exit; +done_testing; diff --git a/t/lib/samples/slowlogs/slow056.txt b/t/lib/samples/slowlogs/slow056.txt new file mode 100644 index 00000000..4b89248d --- /dev/null +++ b/t/lib/samples/slowlogs/slow056.txt @@ -0,0 +1,12 @@ +# Time: 121123 19:56:06.0000001967 +# User@Host: root[root] @ [127.0.0.1] +# Thread_id: 558038 Schema: test_db Last_errno: 0 Killed: 0 +# Query_time: 0.000102 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0 Rows_read: 0 +SET timestamp=1111111111; +use test_db; +# Time: 121123 19:56:06.0000002134 +# User@Host: root[root] @ [127.0.0.1] +# Thread_id: 558032 Schema: test_db Last_errno: 0 Killed: 0 +# Query_time: 0.002515 Lock_time: 0.000197 Rows_sent: 0 Rows_examined: 1 Rows_affected: 1 Rows_read: 0 +SET timestamp=2222222222; +update t set b = b + 30 where user_id=1; diff --git a/t/pt-query-digest/samples/slow056.txt b/t/pt-query-digest/samples/slow056.txt new file mode 100644 index 00000000..8e6571d3 --- /dev/null +++ b/t/pt-query-digest/samples/slow056.txt @@ -0,0 +1,68 @@ + +# Query 1: 0 QPS, 0x concurrency, ID 0x54E0BB9E70EAA792 at byte 596 ______ +# This item is included in the report because it matches --limit. +# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00 +# Query_time sparkline: | ^ | +# Time range: all events occurred at 2012-11-23 19:56:06 +# Attribute pct total min max avg 95% stddev median +# ============ === ======= ======= ======= ======= ======= ======= ======= +# Count 50 1 +# Exec time 96 3ms 3ms 3ms 3ms 3ms 0 3ms +# Lock time 100 197us 197us 197us 197us 197us 0 197us +# Rows sent 0 0 0 0 0 0 0 0 +# Rows examine 100 1 1 1 1 1 0 1 +# Rows affecte 100 1 1 1 1 1 0 1 +# Rows read 0 0 0 0 0 0 0 0 +# Query size 100 39 39 39 39 39 0 39 +# String: +# Databases test_db +# Hosts +# Last errno 0 +# Users root +# Query_time distribution +# 1us +# 10us +# 100us +# 1ms ################################################################ +# 10ms +# 100ms +# 1s +# 10s+ +# Tables +# SHOW TABLE STATUS FROM `test_db` LIKE 't'\G +# SHOW CREATE TABLE `test_db`.`t`\G +update t set b = b + 30 where user_id=1\G +# Converted for EXPLAIN +# EXPLAIN /*!50100 PARTITIONS*/ +select b = b + 30 from t where user_id=1\G + +# Query 2: 0 QPS, 0x concurrency, ID 0xE9800998ECF8427E at byte 0 ________ +# This item is included in the report because it matches --limit. +# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00 +# Query_time sparkline: | ^ | +# Time range: all events occurred at 2012-11-23 19:56:06 +# Attribute pct total min max avg 95% stddev median +# ============ === ======= ======= ======= ======= ======= ======= ======= +# Count 50 1 +# Exec time 3 102us 102us 102us 102us 102us 0 102us +# Lock time 0 0 0 0 0 0 0 0 +# Rows sent 0 0 0 0 0 0 0 0 +# Rows examine 0 0 0 0 0 0 0 0 +# Rows affecte 0 0 0 0 0 0 0 0 +# Rows read 0 0 0 0 0 0 0 0 +# Query size 0 0 0 0 0 0 0 0 +# String: +# Databases test_db +# Hosts +# Last errno 0 +# Users root +# Query_time distribution +# 1us +# 10us +# 100us ################################################################ +# 1ms +# 10ms +# 100ms +# 1s +# 10s+ +/* No query */\G diff --git a/t/pt-query-digest/slowlog_analyses.t b/t/pt-query-digest/slowlog_analyses.t index 0da55e18..978d3994 100644 --- a/t/pt-query-digest/slowlog_analyses.t +++ b/t/pt-query-digest/slowlog_analyses.t @@ -9,10 +9,9 @@ BEGIN { use strict; use warnings FATAL => 'all'; use English qw(-no_match_vars); -use Test::More tests => 44; +use Test::More; use PerconaTest; - require "$trunk/bin/pt-query-digest"; # ############################################################################# @@ -434,7 +433,18 @@ ok( 'Analysis for slow055 (group by blank db bug 924950)' ); +# ############################################################################# +# Bug 1082599: pt-query-digest fails to parse timestamp with no query +# ############################################################################# +ok( + no_diff( + sub { pt_query_digest::main(@args, $sample.'slow056.txt') }, + "t/pt-query-digest/samples/slow056.txt", + ), + 'Analysis for slow056 (no query bug 1082599)' +); + # ############################################################################# # Done. # ############################################################################# -exit; +done_testing;