5.6 slow query log Thead_id becomes Id - 1299387

bin/pt-index-usage

@@ -2772,12 +2772,13 @@ sub new {
    my ( $class ) = @_;
    my $self = {
       pending => [],
+      last_event_offset => undef,
    };
    return bless $self, $class;
 }
 
 my $slow_log_ts_line = qr/^# Time: ([0-9: ]{15})/;
-my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]/;
+my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]\s*(?:Id:\s*(\d+))?/;
 my $slow_log_hd_line = qr{
       ^(?:
       T[cC][pP]\s[pP]ort:\s+\d+ # case differs on windows/unix
@@ -2808,6 +2809,7 @@ sub parse_event {
       or defined($stmt = $next_event->())
    ) {
       my @properties = ('cmd', 'Query', 'pos_in_log', $pos_in_log);
+      $self->{last_event_offset} = $pos_in_log;
       $pos_in_log = $tell->();
 
       if ( $stmt =~ s/$slow_log_hd_line//go ){ # Throw away header lines in log
@@ -2840,19 +2842,29 @@ sub parse_event {
                push @properties, 'ts', $time;
                ++$got_ts;
                if ( !$got_uh
-                  && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
+                  && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
                ) {
-                  PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                  if ($thread_id) {  # 5.6 has the thread id on the User@Host line
-                  push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                     PTDEBUG && _d("Got user, host, ip, Thread_id", $user, $host, $thread_id);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip, 'Thread_id', $thread_id;
+                  }else{
+                     PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                  }
                   ++$got_uh;
                }
             }
 
             elsif ( !$got_uh
-                  && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
+                  && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
             ) {
-               PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                  if ($thread_id) {  # 5.6 has the thread id on the User@Host line
-               push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                     PTDEBUG && _d("Got user, host, ip, Thread_id", $user, $host, $thread_id);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip, 'Thread_id', $thread_id;
+                  }else{
+                     PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                  }
                ++$got_uh;
             }
 
@@ -2933,9 +2945,15 @@ sub parse_event {
 
       PTDEBUG && _d('Properties of event:', Dumper(\@properties));
       my $event = { @properties };
-      if ( $args{stats} ) {
+      if ( !$event->{arg} ) {
-         $args{stats}->{events_read}++;
+         PTDEBUG && _d('Partial event, no arg');
-         $args{stats}->{events_parsed}++;
+      }
+      else {
+         $self->{last_event_offset} = undef;
+         if ( $args{stats} ) {
+            $args{stats}->{events_read}++;
+            $args{stats}->{events_parsed}++;
+         }
       }
       return $event;
    } # EVENT

bin/pt-query-digest

@@ -4972,7 +4972,7 @@ sub new {
 }
 
 my $slow_log_ts_line = qr/^# Time: ([0-9: ]{15})/;
-my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]/;
+my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]\s*(?:Id:\s*(\d+))?/;
 my $slow_log_hd_line = qr{
       ^(?:
       T[cC][pP]\s[pP]ort:\s+\d+ # case differs on windows/unix
@@ -5036,19 +5036,29 @@ sub parse_event {
                push @properties, 'ts', $time;
                ++$got_ts;
                if ( !$got_uh
-                  && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
+                  && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
                ) {
-                  PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                  if ($thread_id) {  # 5.6 has the thread id on the User@Host line
-                  push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                     PTDEBUG && _d("Got user, host, ip, Thread_id", $user, $host, $thread_id);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip, 'Thread_id', $thread_id;
+                  }else{
+                     PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                  }
                   ++$got_uh;
                }
             }
 
             elsif ( !$got_uh
-                  && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
+                  && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
             ) {
-               PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                  if ($thread_id) {  # 5.6 has the thread id on the User@Host line
-               push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                     PTDEBUG && _d("Got user, host, ip, Thread_id", $user, $host, $thread_id);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip, 'Thread_id', $thread_id;
+                  }else{
+                     PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                  }
                ++$got_uh;
             }
 

bin/pt-table-usage

@@ -1556,12 +1556,13 @@ sub new {
    my ( $class ) = @_;
    my $self = {
       pending => [],
+      last_event_offset => undef,
    };
    return bless $self, $class;
 }
 
 my $slow_log_ts_line = qr/^# Time: ([0-9: ]{15})/;
-my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]/;
+my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]\s*(?:Id:\s*(\d+))?/;
 my $slow_log_hd_line = qr{
       ^(?:
       T[cC][pP]\s[pP]ort:\s+\d+ # case differs on windows/unix
@@ -1592,6 +1593,7 @@ sub parse_event {
       or defined($stmt = $next_event->())
    ) {
       my @properties = ('cmd', 'Query', 'pos_in_log', $pos_in_log);
+      $self->{last_event_offset} = $pos_in_log;
       $pos_in_log = $tell->();
 
       if ( $stmt =~ s/$slow_log_hd_line//go ){ # Throw away header lines in log
@@ -1624,19 +1626,29 @@ sub parse_event {
                push @properties, 'ts', $time;
                ++$got_ts;
                if ( !$got_uh
-                  && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
+                  && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
                ) {
-                  PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                  if ($thread_id) {  # 5.6 has the thread id on the User@Host line
-                  push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                     PTDEBUG && _d("Got user, host, ip, Thread_id", $user, $host, $thread_id);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip, 'Thread_id', $thread_id;
+                  }else{
+                     PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                  }
                   ++$got_uh;
                }
             }
 
             elsif ( !$got_uh
-                  && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
+                  && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
             ) {
-               PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                  if ($thread_id) {  # 5.6 has the thread id on the User@Host line
-               push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                     PTDEBUG && _d("Got user, host, ip, Thread_id", $user, $host, $thread_id);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip, 'Thread_id', $thread_id;
+                  }else{
+                     PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                  }
                ++$got_uh;
             }
 
@@ -1676,14 +1688,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;
+                  if ( $l =~ /^\s*[A-Z][a-z_]+: / ) {
-                  $l =~ s/^\s+//;
+                     PTDEBUG && _d("Found NULL query before", $l);
-                  PTDEBUG && _d("Found admin statement", $l);
+                     local $INPUT_RECORD_SEPARATOR = ";\n#";
-                  push @properties, 'cmd', 'Admin', 'arg', $l;
+                     my $rest_of_event = $next_event->();
-                  push @properties, 'bytes', length($properties[-1]);
+                     push @{$self->{pending}}, $l . $rest_of_event;
-                  $found_arg++;
+                     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");
@@ -1706,9 +1729,15 @@ sub parse_event {
 
       PTDEBUG && _d('Properties of event:', Dumper(\@properties));
       my $event = { @properties };
-      if ( $args{stats} ) {
+      if ( !$event->{arg} ) {
-         $args{stats}->{events_read}++;
+         PTDEBUG && _d('Partial event, no arg');
-         $args{stats}->{events_parsed}++;
+      }
+      else {
+         $self->{last_event_offset} = undef;
+         if ( $args{stats} ) {
+            $args{stats}->{events_read}++;
+            $args{stats}->{events_parsed}++;
+         }
       }
       return $event;
    } # EVENT

bin/pt-upgrade

@@ -6537,12 +6537,13 @@ sub new {
    my ( $class ) = @_;
    my $self = {
       pending => [],
+      last_event_offset => undef,
    };
    return bless $self, $class;
 }
 
 my $slow_log_ts_line = qr/^# Time: ([0-9: ]{15})/;
-my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]/;
+my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]\s*(?:Id:\s*(\d+))?/;
 my $slow_log_hd_line = qr{
       ^(?:
       T[cC][pP]\s[pP]ort:\s+\d+ # case differs on windows/unix
@@ -6573,6 +6574,7 @@ sub parse_event {
       or defined($stmt = $next_event->())
    ) {
       my @properties = ('cmd', 'Query', 'pos_in_log', $pos_in_log);
+      $self->{last_event_offset} = $pos_in_log;
       $pos_in_log = $tell->();
 
       if ( $stmt =~ s/$slow_log_hd_line//go ){ # Throw away header lines in log
@@ -6605,19 +6607,29 @@ sub parse_event {
                push @properties, 'ts', $time;
                ++$got_ts;
                if ( !$got_uh
-                  && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
+                  && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
                ) {
-                  PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                  if ($thread_id) {  # 5.6 has the thread id on the User@Host line
-                  push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                     PTDEBUG && _d("Got user, host, ip, Thread_id", $user, $host, $thread_id);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip, 'Thread_id', $thread_id;
+                  }else{
+                     PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                  }
                   ++$got_uh;
                }
             }
 
             elsif ( !$got_uh
-                  && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
+                  && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
             ) {
-               PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                  if ($thread_id) {  # 5.6 has the thread id on the User@Host line
-               push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                     PTDEBUG && _d("Got user, host, ip, Thread_id", $user, $host, $thread_id);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip, 'Thread_id', $thread_id;
+                  }else{
+                     PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                  }
                ++$got_uh;
             }
 
@@ -6698,9 +6710,15 @@ sub parse_event {
 
       PTDEBUG && _d('Properties of event:', Dumper(\@properties));
       my $event = { @properties };
-      if ( $args{stats} ) {
+      if ( !$event->{arg} ) {
-         $args{stats}->{events_read}++;
+         PTDEBUG && _d('Partial event, no arg');
-         $args{stats}->{events_parsed}++;
+      }
+      else {
+         $self->{last_event_offset} = undef;
+         if ( $args{stats} ) {
+            $args{stats}->{events_read}++;
+            $args{stats}->{events_parsed}++;
+         }
       }
       return $event;
    } # EVENT

lib/SlowLogParser.pm

@@ -42,7 +42,7 @@ sub new {
 }
 
 my $slow_log_ts_line = qr/^# Time: ([0-9: ]{15})/;
-my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]/;
+my $slow_log_uh_line = qr/# User\@Host: ([^\[]+|\[[^[]+\]).*?@ (\S*) \[(.*)\]\s*(?:Id:\s*(\d+))?/;
 # These can appear in the log file when it's opened -- for example, when someone
 # runs FLUSH LOGS or the server starts.
 # /usr/sbin/mysqld, Version: 5.0.67-0ubuntu6-log ((Ubuntu)). started with:
@@ -159,10 +159,15 @@ sub parse_event {
                ++$got_ts;
                # The User@Host might be concatenated onto the end of the Time.
                if ( !$got_uh
-                  && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
+                  && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
                ) {
-                  PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                  if ($thread_id) {  # 5.6 has the thread id on the User@Host line
-                  push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                     PTDEBUG && _d("Got user, host, ip, Thread_id", $user, $host, $thread_id);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip, 'Thread_id', $thread_id;
+                  }else{
+                     PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                  }
                   ++$got_uh;
                }
             }
@@ -170,10 +175,15 @@ sub parse_event {
             # Maybe it's the user/host line of a slow query log
             # # User@Host: root[root] @ localhost []
             elsif ( !$got_uh
-                  && ( my ( $user, $host, $ip ) = $line =~ m/$slow_log_uh_line/o )
+                  && ( my ( $user, $host, $ip, $thread_id ) = $line =~ m/$slow_log_uh_line/o )
             ) {
-               PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                  if ($thread_id) {  # 5.6 has the thread id on the User@Host line
-               push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                     PTDEBUG && _d("Got user, host, ip, Thread_id", $user, $host, $thread_id);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip, 'Thread_id', $thread_id;
+                  }else{
+                     PTDEBUG && _d("Got user, host, ip", $user, $host, $ip);
+                     push @properties, 'user', $user, 'host', $host, 'ip', $ip;
+                  }
                ++$got_uh;
             }
 

t/lib/SlowLogParser.t

@@ -1349,6 +1349,70 @@ test_log_parser(
    ],
 );
 
+
+# #############################################################################
+# pt-query-digest fails to parse Thread_id on 5.6 
+# https://bugs.launchpad.net/percona-toolkit/+bug/1299387
+# #############################################################################
+
+# first test with a Percona 5.5 slow log (includes an explicit Thread_id line)
+# (MySQL 5.5 doesn't include thread id)
+test_log_parser(
+   parser => $p,
+   file   => "$sample/p55-slow.log",
+   result => [
+      {  
+        Thread_id     => '1',     # here's our item
+        Bytes_sent    => '64',
+        Killed        => '0',
+        Last_errno    => '0',
+        Lock_time     => '0.000000',
+        Query_time    => '10.000373',
+        Rows_affected => '0',
+        Rows_examined => '0',
+        Rows_read     => '0',
+        Rows_sent     => '1',
+        arg           => 'select sleep(10)',
+        bytes         => 16,
+        cmd           => 'Query',
+        host          => 'localhost',
+        ip            => '127.0.0.1',
+        pos_in_log    => 0,
+        timestamp     => '1405358212',
+        ts            => '140714 14:16:52',
+        user          => 'root'
+      },
+   ],
+);
+
+# now test with a Percona 5.6 slow log. Thread_id is now on the user@host line, and is called 'Id'.
+# (this is in line with MySQL 5.6)
+test_log_parser(
+   parser => $p,
+   file   => "$sample/p56-slow.log",
+   result => [
+      {  
+         Thread_id     => 1,           # here's our item
+         Bytes_sent    => '64',
+         Lock_time     => '0.000000',
+         Query_time    => '11.013723',
+         Rows_affected => '0',
+         Rows_examined => '0',
+         Rows_sent     => '1',
+         arg           => 'select sleep(11)',
+         bytes         => 16,
+         cmd           => 'Query',
+         host          => 'localhost',
+         ip            => '127.0.0.1',
+         pos_in_log    => 0,
+         timestamp     => '1405360304',
+         ts            => '140714 14:51:44',
+         user          => 'root',
+      },
+   ],
+);
+
+
 # #############################################################################
 # Done.
 # #############################################################################

t/lib/samples/slowlogs/p55-slow.log

@@ -0,0 +1,10 @@
+bin/mysqld, Version: 5.5.38-35.2-log (Percona Server (GPL), Release 35.2, Revision 674). started with:
+Tcp port: 3306  Unix socket: (null)
+Time                 Id Command    Argument
+# Time: 140714 14:16:52
+# User@Host: root[root] @ localhost [127.0.0.1]
+# Thread_id: 1  Schema:   Last_errno: 0  Killed: 0
+# Query_time: 10.000373  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0  Rows_affected: 0  Rows_read: 0
+# Bytes_sent: 64
+SET timestamp=1405358212;
+select sleep(10);

t/lib/samples/slowlogs/p56-slow.log

@@ -0,0 +1,10 @@
+bin/mysqld, Version: 5.6.19-67.0-log (Percona Server (GPL), Release 67.0, Revision 618). started with:
+Tcp port: 3306  Unix socket: (null)
+Time                 Id Command    Argument
+# Time: 140714 14:51:44
+# User@Host: root[root] @ localhost [127.0.0.1]  Id:     1
+# Schema:   Last_errno: 0  Killed: 0
+# Query_time: 11.013723  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0  Rows_affected: 0
+# Bytes_sent: 64
+SET timestamp=1405360304;
+select sleep(11);