From 2f1bb594f9228ec6575f9fdf3e4d1e2d0c8324e6 Mon Sep 17 00:00:00 2001 From: Daniel Nichter Date: Mon, 10 Dec 2012 18:11:59 -0700 Subject: [PATCH] Update SlowLogParser in pqd and add test case. --- bin/pt-query-digest | 25 +++++++--- t/pt-query-digest/samples/slow056.txt | 68 +++++++++++++++++++++++++++ t/pt-query-digest/slowlog_analyses.t | 11 +++++ 3 files changed, 97 insertions(+), 7 deletions(-) create mode 100644 t/pt-query-digest/samples/slow056.txt diff --git a/bin/pt-query-digest b/bin/pt-query-digest index 36736753..9a511c5c 100755 --- a/bin/pt-query-digest +++ b/bin/pt-query-digest @@ -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"); diff --git a/t/pt-query-digest/samples/slow056.txt b/t/pt-query-digest/samples/slow056.txt new file mode 100644 index 00000000..8e6571d3 --- /dev/null +++ b/t/pt-query-digest/samples/slow056.txt @@ -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 diff --git a/t/pt-query-digest/slowlog_analyses.t b/t/pt-query-digest/slowlog_analyses.t index 0da55e18..8b250432 100644 --- a/t/pt-query-digest/slowlog_analyses.t +++ b/t/pt-query-digest/slowlog_analyses.t @@ -434,6 +434,17 @@ 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. # #############################################################################