From ec4be9a8835712275a183ad7c684c541f087a3af Mon Sep 17 00:00:00 2001 From: Daniel Nichter Date: Mon, 10 Dec 2012 18:07:36 -0700 Subject: [PATCH] Add and fix test case for special 'no query' events. --- lib/SlowLogParser.pm | 35 ++++++++++++++---- t/lib/SlowLogParser.t | 57 ++++++++++++++++++++++++++++-- t/lib/samples/slowlogs/slow056.txt | 12 +++++++ 3 files changed, 95 insertions(+), 9 deletions(-) create mode 100644 t/lib/samples/slowlogs/slow056.txt 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;