From af185fbc289b248ec4d4f9a15acd68670813b46c Mon Sep 17 00:00:00 2001 From: Frank Cizmich Date: Tue, 15 Jul 2014 15:12:45 -0300 Subject: [PATCH] 5.6 slow query log Thead_id becomes Id - 1299387 --- bin/pt-index-usage | 38 ++++++++++++----- bin/pt-query-digest | 24 +++++++---- bin/pt-table-usage | 63 ++++++++++++++++++++-------- bin/pt-upgrade | 38 ++++++++++++----- lib/SlowLogParser.pm | 24 +++++++---- t/lib/SlowLogParser.t | 64 +++++++++++++++++++++++++++++ t/lib/samples/slowlogs/p55-slow.log | 10 +++++ t/lib/samples/slowlogs/p56-slow.log | 10 +++++ 8 files changed, 220 insertions(+), 51 deletions(-) create mode 100644 t/lib/samples/slowlogs/p55-slow.log create mode 100644 t/lib/samples/slowlogs/p56-slow.log diff --git a/bin/pt-index-usage b/bin/pt-index-usage index ce86a3c7..2aa13ea1 100755 --- a/bin/pt-index-usage +++ b/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); - push @properties, 'user', $user, 'host', $host, 'ip', $ip; + if ($thread_id) { # 5.6 has the thread id on the User@Host line + 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); - push @properties, 'user', $user, 'host', $host, 'ip', $ip; + if ($thread_id) { # 5.6 has the thread id on the User@Host line + 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} ) { - $args{stats}->{events_read}++; - $args{stats}->{events_parsed}++; + if ( !$event->{arg} ) { + PTDEBUG && _d('Partial event, no arg'); + } + else { + $self->{last_event_offset} = undef; + if ( $args{stats} ) { + $args{stats}->{events_read}++; + $args{stats}->{events_parsed}++; + } } return $event; } # EVENT diff --git a/bin/pt-query-digest b/bin/pt-query-digest index 14149ce6..cbd0ddb5 100755 --- a/bin/pt-query-digest +++ b/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); - push @properties, 'user', $user, 'host', $host, 'ip', $ip; + if ($thread_id) { # 5.6 has the thread id on the User@Host line + 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); - push @properties, 'user', $user, 'host', $host, 'ip', $ip; + if ($thread_id) { # 5.6 has the thread id on the User@Host line + 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; } diff --git a/bin/pt-table-usage b/bin/pt-table-usage index 1f41c0ea..3e2166b6 100755 --- a/bin/pt-table-usage +++ b/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); - push @properties, 'user', $user, 'host', $host, 'ip', $ip; + if ($thread_id) { # 5.6 has the thread id on the User@Host line + 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); - push @properties, 'user', $user, 'host', $host, 'ip', $ip; + if ($thread_id) { # 5.6 has the thread id on the User@Host line + 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; - $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"); @@ -1706,9 +1729,15 @@ sub parse_event { PTDEBUG && _d('Properties of event:', Dumper(\@properties)); my $event = { @properties }; - if ( $args{stats} ) { - $args{stats}->{events_read}++; - $args{stats}->{events_parsed}++; + if ( !$event->{arg} ) { + PTDEBUG && _d('Partial event, no arg'); + } + else { + $self->{last_event_offset} = undef; + if ( $args{stats} ) { + $args{stats}->{events_read}++; + $args{stats}->{events_parsed}++; + } } return $event; } # EVENT diff --git a/bin/pt-upgrade b/bin/pt-upgrade index 0b2deda1..c6da613b 100755 --- a/bin/pt-upgrade +++ b/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); - push @properties, 'user', $user, 'host', $host, 'ip', $ip; + if ($thread_id) { # 5.6 has the thread id on the User@Host line + 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); - push @properties, 'user', $user, 'host', $host, 'ip', $ip; + if ($thread_id) { # 5.6 has the thread id on the User@Host line + 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} ) { - $args{stats}->{events_read}++; - $args{stats}->{events_parsed}++; + if ( !$event->{arg} ) { + PTDEBUG && _d('Partial event, no arg'); + } + else { + $self->{last_event_offset} = undef; + if ( $args{stats} ) { + $args{stats}->{events_read}++; + $args{stats}->{events_parsed}++; + } } return $event; } # EVENT diff --git a/lib/SlowLogParser.pm b/lib/SlowLogParser.pm index b645db01..0ee10537 100644 --- a/lib/SlowLogParser.pm +++ b/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); - push @properties, 'user', $user, 'host', $host, 'ip', $ip; + if ($thread_id) { # 5.6 has the thread id on the User@Host line + 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); - push @properties, 'user', $user, 'host', $host, 'ip', $ip; + if ($thread_id) { # 5.6 has the thread id on the User@Host line + 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; } diff --git a/t/lib/SlowLogParser.t b/t/lib/SlowLogParser.t index 1fb5ec4d..a055dc01 100644 --- a/t/lib/SlowLogParser.t +++ b/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. # ############################################################################# diff --git a/t/lib/samples/slowlogs/p55-slow.log b/t/lib/samples/slowlogs/p55-slow.log new file mode 100644 index 00000000..0ed9541f --- /dev/null +++ b/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); diff --git a/t/lib/samples/slowlogs/p56-slow.log b/t/lib/samples/slowlogs/p56-slow.log new file mode 100644 index 00000000..f0325479 --- /dev/null +++ b/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);