mirror of
https://github.com/percona/percona-toolkit.git
synced 2025-12-25 02:01:13 +08:00
Merge fix-slowlog-ts-bug-1082599
This commit is contained in:
Daniel Nichter
@@ -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");
|
||||
|
||||
@@ -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,
|
||||
|
||||
@@ -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;
|
||||
|
||||
12
t/lib/samples/slowlogs/slow056.txt
Normal file
12
t/lib/samples/slowlogs/slow056.txt
Normal file
@@ -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;
|
||||
68
t/pt-query-digest/samples/slow056.txt
Normal file
68
t/pt-query-digest/samples/slow056.txt
Normal file
@@ -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
|
||||
@@ -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;
|
||||
|
||||
Reference in New Issue
Block a user