From 2f9ab4081ae46c386bb8ce876360f85331733aaa Mon Sep 17 00:00:00 2001 From: Daniel Nichter Date: Tue, 8 Nov 2011 12:53:50 -0700 Subject: [PATCH] Fix prepared report for statements without corresponding prep or exec. --- bin/pt-query-digest | 28 +++++++-- lib/PerconaTest.pm | 1 + lib/QueryReportFormatter.pm | 28 +++++++-- t/lib/QueryReportFormatter.t | 63 ++++++++++++++++++- .../QueryReportFormatter/report002.txt | 6 +- .../QueryReportFormatter/report030.txt | 5 ++ t/lib/samples/tcpdump/tcpdump041.txt | 22 +++++++ .../prepared_statements_analyses.t | 14 ++++- t/pt-query-digest/samples/tcpdump041.txt | 52 +++++++++++++++ 9 files changed, 200 insertions(+), 19 deletions(-) create mode 100644 t/lib/samples/QueryReportFormatter/report030.txt create mode 100644 t/lib/samples/tcpdump/tcpdump041.txt create mode 100644 t/pt-query-digest/samples/tcpdump041.txt diff --git a/bin/pt-query-digest b/bin/pt-query-digest index 21781e11..21dec40e 100755 --- a/bin/pt-query-digest +++ b/bin/pt-query-digest @@ -6877,12 +6877,28 @@ sub prepared { } if ( !$seen_prepared{$prep_stmt}++ ) { - $exec = $ea->results->{classes}->{$exec_stmt}; - $exec_r = $exec->{Query_time}->{sum}; - $exec_cnt = $exec->{Query_time}->{cnt}; - $prep = $ea->results->{classes}->{$prep_stmt}; - $prep_r = $prep->{Query_time}->{sum}; - $prep_cnt = scalar keys %{$prep->{Statement_id}->{unq}}, + if ( exists $ea->results->{classes}->{$exec_stmt} ) { + $exec = $ea->results->{classes}->{$exec_stmt}; + $exec_r = $exec->{Query_time}->{sum}; + $exec_cnt = $exec->{Query_time}->{cnt}; + } + else { + MKDEBUG && _d('Statement prepared but not executed:', $item); + $exec_r = 0; + $exec_cnt = 0; + } + + if ( exists $ea->results->{classes}->{$prep_stmt} ) { + $prep = $ea->results->{classes}->{$prep_stmt}; + $prep_r = $prep->{Query_time}->{sum}; + $prep_cnt = scalar keys %{$prep->{Statement_id}->{unq}}, + } + else { + MKDEBUG && _d('Statement executed but not prepared:', $item); + $prep_r = 0; + $prep_cnt = 0; + } + push @prepared, { prep_r => $prep_r, prep_cnt => $prep_cnt, diff --git a/lib/PerconaTest.pm b/lib/PerconaTest.pm index 2f48cc2e..8c6a0bfc 100644 --- a/lib/PerconaTest.pm +++ b/lib/PerconaTest.pm @@ -163,6 +163,7 @@ sub output { close *output_fh; if ( $EVAL_ERROR ) { die $EVAL_ERROR if $die; + warn $EVAL_ERROR unless $args{stderr}; return $EVAL_ERROR; } diff --git a/lib/QueryReportFormatter.pm b/lib/QueryReportFormatter.pm index 62ac05dd..1e71b685 100644 --- a/lib/QueryReportFormatter.pm +++ b/lib/QueryReportFormatter.pm @@ -1018,12 +1018,28 @@ sub prepared { # Report each PREPARE/EXECUTE pair once. if ( !$seen_prepared{$prep_stmt}++ ) { - $exec = $ea->results->{classes}->{$exec_stmt}; - $exec_r = $exec->{Query_time}->{sum}; - $exec_cnt = $exec->{Query_time}->{cnt}; - $prep = $ea->results->{classes}->{$prep_stmt}; - $prep_r = $prep->{Query_time}->{sum}; - $prep_cnt = scalar keys %{$prep->{Statement_id}->{unq}}, + if ( exists $ea->results->{classes}->{$exec_stmt} ) { + $exec = $ea->results->{classes}->{$exec_stmt}; + $exec_r = $exec->{Query_time}->{sum}; + $exec_cnt = $exec->{Query_time}->{cnt}; + } + else { + MKDEBUG && _d('Statement prepared but not executed:', $item); + $exec_r = 0; + $exec_cnt = 0; + } + + if ( exists $ea->results->{classes}->{$prep_stmt} ) { + $prep = $ea->results->{classes}->{$prep_stmt}; + $prep_r = $prep->{Query_time}->{sum}; + $prep_cnt = scalar keys %{$prep->{Statement_id}->{unq}}, + } + else { + MKDEBUG && _d('Statement executed but not prepared:', $item); + $prep_r = 0; + $prep_cnt = 0; + } + push @prepared, { prep_r => $prep_r, prep_cnt => $prep_cnt, diff --git a/t/lib/QueryReportFormatter.t b/t/lib/QueryReportFormatter.t index 78294731..09b86926 100644 --- a/t/lib/QueryReportFormatter.t +++ b/t/lib/QueryReportFormatter.t @@ -9,7 +9,7 @@ BEGIN { use strict; use warnings FATAL => 'all'; use English qw(-no_match_vars); -use Test::More tests => 43; +use Test::More tests => 44; use Data::Dumper; $Data::Dumper::Indent = 1; @@ -1010,8 +1010,11 @@ $events = [ }, ]; $ea = new EventAggregator( - groupby => 'fingerprint', - worst => 'Query_time', + groupby => 'fingerprint', + worst => 'Query_time', + type_for => { + Statement_id => 'string', + }, ); foreach my $event ( @$events ) { $ea->aggregate($event); @@ -1499,6 +1502,60 @@ ok( 'Sparkchart in event header' ); +# ############################################################################ +# Bug 887688: Prepared statements crash pt-query-digest +# ############################################################################ + +# PREP without EXEC +$events = [ + { + Query_time => '0.000286', + Warning_count => 0, + arg => 'PREPARE SELECT i FROM d.t WHERE i=?', + fingerprint => 'prepare select i from d.t where i=?', + bytes => 35, + cmd => 'Query', + db => undef, + pos_in_log => 0, + ts => '091208 09:23:49.637394', + Statement_id => 1, + }, +]; +$ea = new EventAggregator( + groupby => 'fingerprint', + worst => 'Query_time', + type_for => { + Statement_id => 'string', + }, +); +foreach my $event ( @$events ) { + $ea->aggregate($event); +} +$ea->calculate_statistical_metrics(); +$report = new ReportFormatter( + line_width => 82, + extend_right => 1, +); +$qrf->set_report_formatter(report=>'prepared', formatter=>$report); +ok( + no_diff( + sub { + $qrf->print_reports( + reports => ['prepared'], + ea => $ea, + worst => [ + ['prepare select i from d.t where i=?', 'top', 1], + ], + orderby => 'Query_time', + groupby => 'fingerprint', + variations => [qw(arg)], + ); + }, + "t/lib/samples/QueryReportFormatter/report030.txt", + ), + "PREP without EXEC (bug 887688)" +); + # ############################################################################# # Done. # ############################################################################# diff --git a/t/lib/samples/QueryReportFormatter/report002.txt b/t/lib/samples/QueryReportFormatter/report002.txt index a77a2cc2..fbaedf8b 100644 --- a/t/lib/samples/QueryReportFormatter/report002.txt +++ b/t/lib/samples/QueryReportFormatter/report002.txt @@ -8,10 +8,10 @@ # Count 50 1 # Exec time 99 30ms 30ms 30ms 30ms 30ms 0 30ms # Query size 51 37 37 37 37 37 0 37 -# Statement id 50 2 2 2 2 2 0 2 # Warning coun 0 0 0 0 0 0 0 0 # String: # cmd Query +# Statement id 2 # Query_time distribution # 1us # 10us @@ -39,10 +39,10 @@ SELECT i FROM d.t WHERE i="3"\G # Count 50 1 # Exec time 0 286us 286us 286us 286us 286us 0 286us # Query size 48 35 35 35 35 35 0 35 -# Statement id 50 2 2 2 2 2 0 2 # Warning coun 0 0 0 0 0 0 0 0 # String: # cmd Query +# Statement id 2 # Query_time distribution # 1us # 10us @@ -64,4 +64,4 @@ SELECT i FROM d.t WHERE i=?\G # Prepared statements # Rank Query ID PREP PREP Response EXEC EXEC Response Item # ==== ================== ==== ============= ==== ============= ========== -# 1 0x3F79759E7FA2F117 0 0.0003 0.9% 1 0.0303 99.1% SELECT d.t +# 1 0x3F79759E7FA2F117 1 0.0003 0.9% 1 0.0303 99.1% SELECT d.t diff --git a/t/lib/samples/QueryReportFormatter/report030.txt b/t/lib/samples/QueryReportFormatter/report030.txt new file mode 100644 index 00000000..c373570c --- /dev/null +++ b/t/lib/samples/QueryReportFormatter/report030.txt @@ -0,0 +1,5 @@ + +# Prepared statements +# Rank Query ID PREP PREP Response EXEC EXEC Response Item +# ==== ================== ==== ============= ==== ============= ========== +# 1 0xAA8E9FA785927259 1 0.0003 100.0% 0 0.0000 0.0% SELECT d.t diff --git a/t/lib/samples/tcpdump/tcpdump041.txt b/t/lib/samples/tcpdump/tcpdump041.txt new file mode 100644 index 00000000..87e299ea --- /dev/null +++ b/t/lib/samples/tcpdump/tcpdump041.txt @@ -0,0 +1,22 @@ +2009-12-08 09:23:49.637108 IP 127.0.0.1.58619 > 127.0.0.1.12345: tcp 32 + 0x0000: 4508 0054 b468 4000 4006 8831 7f00 0001 + 0x0010: 7f00 0001 e4fb 3039 47e2 1612 4850 bc0a + 0x0020: 8018 0101 fe48 0000 0101 080a 000f a420 + 0x0030: 000f a13c 1c00 0000 1653 454c 4543 5420 + 0x0040: 6920 4652 4f4d 2064 2e74 2057 4845 5245 + 0x0050: 2069 3d3f +2009-12-08 09:23:49.637194 IP 127.0.0.1.12345 > 127.0.0.1.58619: tcp 0 + 0x0000: 4508 0034 1ab3 4000 4006 2207 7f00 0001 + 0x0010: 7f00 0001 3039 e4fb 4850 bc0a 47e2 1632 + 0x0020: 8010 0100 b7b7 0000 0101 080a 000f a420 + 0x0030: 000f a420 +2009-12-08 09:23:49.637394 IP 127.0.0.1.12345 > 127.0.0.1.58619: tcp 92 + 0x0000: 4508 0090 1ab4 4000 4006 21aa 7f00 0001 + 0x0010: 7f00 0001 3039 e4fb 4850 bc0a 47e2 1632 + 0x0020: 8018 0100 fe84 0000 0101 080a 000f a420 + 0x0030: 000f a420 0c00 0001 0002 0000 0001 0001 + 0x0040: 0000 0000 1700 0002 0364 6566 0000 0001 + 0x0050: 3f00 0c3f 0000 0000 00fd 8000 0000 0005 + 0x0060: 0000 03fe 0000 0200 1b00 0004 0364 6566 + 0x0070: 0164 0174 0174 0169 0169 0c3f 000b 0000 + 0x0080: 0003 0000 0000 0005 0000 05fe 0000 0200 diff --git a/t/pt-query-digest/prepared_statements_analyses.t b/t/pt-query-digest/prepared_statements_analyses.t index f96f270a..f5c9a422 100644 --- a/t/pt-query-digest/prepared_statements_analyses.t +++ b/t/pt-query-digest/prepared_statements_analyses.t @@ -9,7 +9,7 @@ BEGIN { use strict; use warnings FATAL => 'all'; use English qw(-no_match_vars); -use Test::More tests => 6; +use Test::More tests => 7; use PerconaTest; @@ -69,6 +69,18 @@ ok( 'Analysis for tcpdump033 with prepared statements report' ); +# ############################################################################ +# Bug 887688: Prepared statements crash pt-query-digest +# ############################################################################ +ok( + no_diff( + sub { pt_query_digest::main(@args, $sample.'tcpdump041.txt', + '--report-format', 'header,query_report,profile,prepared') }, + "t/pt-query-digest/samples/tcpdump041.txt", + ), + 'Analysis for tcpdump041 (bug 887688)' +); + # ############################################################################# # Done. # ############################################################################# diff --git a/t/pt-query-digest/samples/tcpdump041.txt b/t/pt-query-digest/samples/tcpdump041.txt new file mode 100644 index 00000000..09edac73 --- /dev/null +++ b/t/pt-query-digest/samples/tcpdump041.txt @@ -0,0 +1,52 @@ + +# Overall: 1 total, 1 unique, 0 QPS, 0x concurrency ______________________ +# Time range: all events occurred at 2009-12-08 09:23:49.637394 +# Attribute total min max avg 95% stddev median +# ============ ======= ======= ======= ======= ======= ======= ======= +# Exec time 286us 286us 286us 286us 286us 0 286us +# Rows affecte 0 0 0 0 0 0 0 +# Query size 35 35 35 35 35 0 35 +# Warning coun 0 0 0 0 0 0 0 + +# Query 1: 0 QPS, 0x concurrency, ID 0xAA8E9FA785927259 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 2009-12-08 09:23:49.637394 +# Attribute pct total min max avg 95% stddev median +# ============ === ======= ======= ======= ======= ======= ======= ======= +# Count 100 1 +# Exec time 100 286us 286us 286us 286us 286us 0 286us +# Rows affecte 0 0 0 0 0 0 0 0 +# Query size 100 35 35 35 35 35 0 35 +# Warning coun 0 0 0 0 0 0 0 0 +# String: +# Errors none +# Hosts 127.0.0.1 +# Statement id 2 +# Query_time distribution +# 1us +# 10us +# 100us ################################################################ +# 1ms +# 10ms +# 100ms +# 1s +# 10s+ +# Tables +# SHOW TABLE STATUS FROM `d` LIKE 't'\G +# SHOW CREATE TABLE `d`.`t`\G +PREPARE SELECT i FROM d.t WHERE i=?\G +# Converted for EXPLAIN +# EXPLAIN /*!50100 PARTITIONS*/ +SELECT i FROM d.t WHERE i=?\G + +# Profile +# Rank Query ID Response time Calls R/Call Apdx V/M Item +# ==== ================== ============= ===== ====== ==== ===== ========== +# 1 0xAA8E9FA785927259 0.0003 100.0% 1 0.0003 1.00 0.00 SELECT d.t + +# Prepared statements +# Rank Query ID PREP PREP Response EXEC EXEC Response Item +# ==== ================== ==== ============= ==== ============= ========== +# 1 0xAA8E9FA785927259 1 0.0003 100.0% 0 0.0000 0.0% SELECT d.t