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

[Daniel Nichter]

[Daniel Nichter (daniel-nichter)]

review: Approve

=== 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 @@
 
             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");

=== 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 @@
             # 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,

=== 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 @@
 use strict;
 use warnings FATAL => 'all';
 use English qw(-no_match_vars);
-use Test::More tests => 48;
 
+use Test::More;
 use SlowLogParser;
 use PerconaTest;
 
@@ -1297,6 +1297,59 @@
 );
 
 # #############################################################################
+# 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.
 # #############################################################################
 my $output = '';
@@ -1310,4 +1363,4 @@
    qr/Complete test coverage/,
    '_d() works'
 );
-exit;
+done_testing;

=== 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 @@
+# 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;

=== 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 @@
+
+# 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

=== 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 @@
 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";
 
 # #############################################################################
@@ -435,6 +434,17 @@
 );
 
 # #############################################################################
+# 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;