From c3ff5300375d6203343f57079cc1a4d8c7b79b19 Mon Sep 17 00:00:00 2001 From: Daniel Nichter Date: Fri, 16 Aug 2013 18:21:57 -0700 Subject: [PATCH] Add Query_time histogram to json output. --- bin/pt-query-digest | 11 + lib/JSONReportFormatter.pm | 14 ++ t/lib/JSONReportFormatter.t | 170 +++++++++++++++ .../JSONReportFormatter/report001.json | 205 ++++++++++++++++++ .../samples/json/slow002-anon.txt | 12 + t/pt-query-digest/samples/json/slow002.txt | 12 + t/pt-query-digest/samples/json/tcpdump021.txt | 36 +++ 7 files changed, 460 insertions(+) create mode 100644 t/lib/JSONReportFormatter.t create mode 100644 t/lib/samples/JSONReportFormatter/report001.json diff --git a/bin/pt-query-digest b/bin/pt-query-digest index c9a32790..a4e79a9a 100755 --- a/bin/pt-query-digest +++ b/bin/pt-query-digest @@ -8023,6 +8023,17 @@ override query_report => sub { } } + my $vals = $stats->{Query_time}->{all}; + if ( defined $vals && scalar %$vals ) { + my @buck_tens = $ea->buckets_of(10); + my @distro = map { 0 } (0 .. 7); + my @buckets = map { 0 } (0..999); + map { $buckets[$_] = $vals->{$_} } keys %$vals; + $vals = \@buckets; # repoint vals from given hashref to our array + map { $distro[$buck_tens[$_]] += $vals->[$_] } (1 .. @$vals - 1); + $class->{histograms}->{Query_time} = \@distro; + } # histogram + $class->{metrics} = \%metrics; if ( @tables ) { $class->{tables} = \@tables; diff --git a/lib/JSONReportFormatter.pm b/lib/JSONReportFormatter.pm index 465127a2..4e8fa320 100644 --- a/lib/JSONReportFormatter.pm +++ b/lib/JSONReportFormatter.pm @@ -368,6 +368,20 @@ override query_report => sub { } } + # Add reponse time histogram for Query_time + my $vals = $stats->{Query_time}->{all}; + if ( defined $vals && scalar %$vals ) { + # TODO: this is broken. + my @buck_tens = $ea->buckets_of(10); + my @distro = map { 0 } (0 .. 7); + my @buckets = map { 0 } (0..999); + map { $buckets[$_] = $vals->{$_} } keys %$vals; + $vals = \@buckets; # repoint vals from given hashref to our array + map { $distro[$buck_tens[$_]] += $vals->[$_] } (1 .. @$vals - 1); + # @distro = qw(1us 10us 100us 1ms 10ms 100ms 1s 10s+) + $class->{histograms}->{Query_time} = \@distro; + } # histogram + $class->{metrics} = \%metrics; if ( @tables ) { $class->{tables} = \@tables; diff --git a/t/lib/JSONReportFormatter.t b/t/lib/JSONReportFormatter.t new file mode 100644 index 00000000..4a31a78d --- /dev/null +++ b/t/lib/JSONReportFormatter.t @@ -0,0 +1,170 @@ +#!/usr/bin/perl + +BEGIN { + die "The PERCONA_TOOLKIT_BRANCH environment variable is not set.\n" + unless $ENV{PERCONA_TOOLKIT_BRANCH} && -d $ENV{PERCONA_TOOLKIT_BRANCH}; + unshift @INC, "$ENV{PERCONA_TOOLKIT_BRANCH}/lib"; + $ENV{PTTEST_PRETTY_JSON} = 1; + +}; + +use strict; +use warnings FATAL => 'all'; +use English qw(-no_match_vars); +use Test::More; + +use Data::Dumper; +$Data::Dumper::Indent = 1; +$Data::Dumper::Sortkeys = 1; +$Data::Dumper::Quotekeys = 0; + +use JSONReportFormatter; +use OptionParser; +use DSNParser; +use EventAggregator; +use QueryRewriter; +use QueryParser; +use Quoter; +use PerconaTest; + +my ($result, $events, $expected); + +my $o = new OptionParser(description=>'JSONReportFormatter'); +my $q = new Quoter(); +my $qp = new QueryParser(); +my $qr = new QueryRewriter(QueryParser=>$qp); + +$o->get_specs("$trunk/bin/pt-query-digest"); + +my $j = new JSONReportFormatter( + OptionParser => $o, + QueryRewriter => $qr, + QueryParser => $qp, + Quoter => $q, +); + +my $ea = new EventAggregator( + groupby => 'fingerprint', + worst => 'Query_time', + attributes => { + Query_time => [qw(Query_time)], + Lock_time => [qw(Lock_time)], + user => [qw(user)], + ts => [qw(ts)], + Rows_sent => [qw(Rows_sent)], + Rows_examined => [qw(Rows_examined)], + db => [qw(db)], + }, +); + +isa_ok( + $j, + 'JSONReportFormatter' +) or die "Cannot create a JSONReportFormatter"; + +$events = [ + { ts => '071015 21:43:52', + cmd => 'Query', + user => 'root', + host => 'localhost', + ip => '', + arg => "SELECT id FROM users WHERE name='foo'", + Query_time => '8.000652', + Lock_time => '0.000109', + Rows_sent => 1, + Rows_examined => 1, + pos_in_log => 1, + db => 'test3', + }, + { ts => '071015 21:43:52', + cmd => 'Query', + user => 'root', + host => 'localhost', + ip => '', + arg => + "INSERT IGNORE INTO articles (id, body,)VALUES(3558268,'sample text')", + Query_time => '1.001943', + Lock_time => '0.000145', + Rows_sent => 0, + Rows_examined => 0, + pos_in_log => 2, + db => 'test1', + }, + { ts => '071015 21:43:53', + cmd => 'Query', + user => 'bob', + host => 'localhost', + ip => '', + arg => "SELECT id FROM users WHERE name='bar'", + Query_time => '1.000682', + Lock_time => '0.000201', + Rows_sent => 1, + Rows_examined => 2, + pos_in_log => 5, + db => 'test1', + } +]; + +# Here's the breakdown of values for those three events: +# +# ATTRIBUTE VALUE BUCKET VALUE RANGE +# Query_time => 8.000652 326 7.700558026 range [7.700558026, 8.085585927) +# Query_time => 1.001943 284 0.992136979 range [0.992136979, 1.041743827) +# Query_time => 1.000682 284 0.992136979 range [0.992136979, 1.041743827) +# -------- ----------- +# 10.003277 9.684831984 +# +# Lock_time => 0.000109 97 0.000108186 range [0.000108186, 0.000113596) +# Lock_time => 0.000145 103 0.000144980 range [0.000144980, 0.000152229) +# Lock_time => 0.000201 109 0.000194287 range [0.000194287, 0.000204002) +# -------- ----------- +# 0.000455 0.000447453 +# +# Rows_sent => 1 284 0.992136979 range [0.992136979, 1.041743827) +# Rows_sent => 0 0 0 +# Rows_sent => 1 284 0.992136979 range [0.992136979, 1.041743827) +# -------- ----------- +# 2 1.984273958 +# +# Rows_exam => 1 284 0.992136979 range [0.992136979, 1.041743827) +# Rows_exam => 0 0 0 +# Rows_exam => 2 298 1.964363355, range [1.964363355, 2.062581523) +# -------- ----------- +# 3 2.956500334 + +# I hand-checked these values with my TI-83 calculator. +# They are, without a doubt, correct. + +foreach my $event (@$events) { + $event->{fingerprint} = $qr->fingerprint( $event->{arg} ); + $ea->aggregate($event); +} +$ea->calculate_statistical_metrics(apdex_t=>1); +my %top_spec = ( + attrib => 'Query_time', + orderby => 'sum', + total => 100, + count => undef, +); +@top_spec{qw(ol_attrib ol_limit ol_freq)} = split(/:/, "Query_time:1:10"); +my ($worst, $other) = $ea->top_events(%top_spec); +$result = $j->query_report( + ea => $ea, + worst => $worst, + orderby => 'Query_time', + groupby => 'fingerprint', +); + +ok( + no_diff( + $result, + "t/lib/samples/JSONReportFormatter/report001.json", + cmd_output => 1, + ), + 'Basic output' +) or diag($test_diff); + +# ############################################################################# +# Done. +# ############################################################################# +done_testing; diff --git a/t/lib/samples/JSONReportFormatter/report001.json b/t/lib/samples/JSONReportFormatter/report001.json new file mode 100644 index 00000000..27d57183 --- /dev/null +++ b/t/lib/samples/JSONReportFormatter/report001.json @@ -0,0 +1,205 @@ +{ + "classes" : [ + { + "attribute" : "fingerprint", + "checksum" : "82860EDA9A88FCC5", + "distillate" : "SELECT users", + "example" : { + "query" : "SELECT id FROM users WHERE name='foo'", + "ts" : "2007-10-15 21:43:52" + }, + "fingerprint" : "select id from users where name=?", + "histograms" : { + "Query_time" : [ + 0, + 0, + 0, + 0, + 0, + 0, + 2, + 0 + ] + }, + "metrics" : { + "Lock_time" : { + "avg" : "0.000155", + "max" : "0.000201", + "median" : "0.000155", + "min" : "0.000109", + "pct" : "0.666667", + "pct_95" : "0.000201", + "stddev" : "0.000065", + "sum" : "0.000310" + }, + "Query_time" : { + "avg" : "4.500667", + "max" : "8.000652", + "median" : "4.500667", + "min" : "1.000682", + "pct" : "0.666667", + "pct_95" : "8.000652", + "stddev" : "4.949726", + "sum" : "9.001334" + }, + "Rows_examined" : { + "avg" : "1", + "max" : "2", + "median" : "1", + "min" : "1", + "pct" : "0", + "pct_95" : "2", + "stddev" : "0", + "sum" : "3" + }, + "Rows_sent" : { + "avg" : "1", + "max" : "1", + "median" : "1", + "min" : "1", + "pct" : "0", + "pct_95" : "1", + "stddev" : "0", + "sum" : "2" + }, + "db" : { + "value" : "test3" + }, + "user" : { + "value" : "root" + } + }, + "query_count" : null, + "tables" : [ + { + "create" : "SHOW CREATE TABLE `test3`.`users`\\G", + "status" : "SHOW TABLE STATUS FROM `test3` LIKE 'users'\\G" + } + ], + "ts_max" : "2007-10-15 21:43:53", + "ts_min" : "2007-10-15 21:43:52" + }, + { + "attribute" : "fingerprint", + "checksum" : "1087A32FED3B7EBB", + "distillate" : "INSERT articles", + "example" : { + "query" : "INSERT IGNORE INTO articles (id, body,)VALUES(3558268,'sample text')", + "ts" : "2007-10-15 21:43:52" + }, + "fingerprint" : "insert ignore into articles (id, body,)values(?+)", + "histograms" : { + "Query_time" : [ + 0, + 0, + 0, + 0, + 0, + 0, + 1, + 0 + ] + }, + "metrics" : { + "Lock_time" : { + "avg" : "0.000145", + "max" : "0.000145", + "median" : "0.000145", + "min" : "0.000145", + "pct" : "0.333333", + "pct_95" : "0.000145", + "stddev" : "0.000000", + "sum" : "0.000145" + }, + "Query_time" : { + "avg" : "1.001943", + "max" : "1.001943", + "median" : "1.001943", + "min" : "1.001943", + "pct" : "0.333333", + "pct_95" : "1.001943", + "stddev" : "0.000000", + "sum" : "1.001943" + }, + "Rows_examined" : { + "avg" : "0", + "max" : "0", + "median" : "0", + "min" : "0", + "pct" : "0", + "pct_95" : "0", + "stddev" : "0", + "sum" : "0" + }, + "Rows_sent" : { + "avg" : "0", + "max" : "0", + "median" : "0", + "min" : "0", + "pct" : "0", + "pct_95" : "0", + "stddev" : "0", + "sum" : "0" + }, + "db" : { + "value" : "test1" + }, + "user" : { + "value" : "root" + } + }, + "query_count" : null, + "tables" : [ + { + "create" : "SHOW CREATE TABLE `test1`.`articles`\\G", + "status" : "SHOW TABLE STATUS FROM `test1` LIKE 'articles'\\G" + } + ], + "ts_max" : "2007-10-15 21:43:52", + "ts_min" : "2007-10-15 21:43:52" + } + ], + "global" : { + "files" : null, + "metrics" : { + "Lock_time" : { + "avg" : "0.000152", + "max" : "0.000201", + "median" : "0.000145", + "min" : "0.000109", + "pct_95" : "0.000194", + "stddev" : "0.000035", + "sum" : "0.000455" + }, + "Query_time" : { + "avg" : "3.334426", + "max" : "8.000652", + "median" : "0.992137", + "min" : "1.000682", + "pct_95" : "7.700558", + "stddev" : "3.162380", + "sum" : "10.003277" + }, + "Rows_examined" : { + "avg" : "1", + "max" : "2", + "median" : "0", + "min" : "0", + "pct_95" : "1", + "stddev" : "0", + "sum" : "3" + }, + "Rows_sent" : { + "avg" : "0", + "max" : "1", + "median" : "0", + "min" : "0", + "pct_95" : "0", + "stddev" : "0", + "sum" : "2" + } + }, + "query_count" : 3, + "unique_query_count" : 2 + } +} diff --git a/t/pt-query-digest/samples/json/slow002-anon.txt b/t/pt-query-digest/samples/json/slow002-anon.txt index 42791f45..f2790445 100644 --- a/t/pt-query-digest/samples/json/slow002-anon.txt +++ b/t/pt-query-digest/samples/json/slow002-anon.txt @@ -6,6 +6,18 @@ "checksum" : "66825DDC008FFA89", "distillate" : "UPDATE db?.tuningdetail_?_? db?.gonzo", "fingerprint" : "update d?tuningdetail_?_? n inner join d?gonzo a using(gonzo) set n.column? = a.column?, n.word? = a.word?", + "histograms" : { + "Query_time" : [ + 0, + 0, + 0, + 0, + 0, + 1, + 0, + 0 + ] + }, "metrics" : { "Filesort" : { "yes" : "0" diff --git a/t/pt-query-digest/samples/json/slow002.txt b/t/pt-query-digest/samples/json/slow002.txt index c6243729..cfe365ed 100644 --- a/t/pt-query-digest/samples/json/slow002.txt +++ b/t/pt-query-digest/samples/json/slow002.txt @@ -11,6 +11,18 @@ "ts" : "2007-12-18 11:48:27" }, "fingerprint" : "update d?tuningdetail_?_? n inner join d?gonzo a using(gonzo) set n.column? = a.column?, n.word? = a.word?", + "histograms" : { + "Query_time" : [ + 0, + 0, + 0, + 0, + 0, + 1, + 0, + 0 + ] + }, "metrics" : { "Filesort" : { "yes" : "0" diff --git a/t/pt-query-digest/samples/json/tcpdump021.txt b/t/pt-query-digest/samples/json/tcpdump021.txt index 6caf4681..22ec71a3 100644 --- a/t/pt-query-digest/samples/json/tcpdump021.txt +++ b/t/pt-query-digest/samples/json/tcpdump021.txt @@ -11,6 +11,18 @@ "ts" : "2009-12-08 09:23:49.637394" }, "fingerprint" : "prepare select i from d.t where i=?", + "histograms" : { + "Query_time" : [ + 0, + 0, + 1, + 0, + 0, + 0, + 0, + 0 + ] + }, "metrics" : { "No_good_index_used" : { "yes" : "0" @@ -75,6 +87,18 @@ "ts" : "2009-12-08 09:23:49.637892" }, "fingerprint" : "execute select i from d.t where i=?", + "histograms" : { + "Query_time" : [ + 0, + 0, + 1, + 0, + 0, + 0, + 0, + 0 + ] + }, "metrics" : { "No_good_index_used" : { "yes" : "0" @@ -138,6 +162,18 @@ "ts" : "2009-12-08 09:23:49.638381" }, "fingerprint" : "administrator command: Quit", + "histograms" : { + "Query_time" : [ + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + }, "metrics" : { "No_good_index_used" : { "yes" : "0"