From 76b512c7a03a04ae4367cc11fd3c591368f121b5 Mon Sep 17 00:00:00 2001 From: Jesper Wisborg Krogh Date: Tue, 21 Jun 2016 21:59:59 +1000 Subject: [PATCH] Bug #23621189 PS_TRACE_STATEMENT_DIGEST FAILS AT EXPLAIN OR NO FOUND QUERIES The ps_trace_statement_digest() procedure did not handle some conditions: * Queries (such as SHOW) that does not support EXPLAIN * Queries where one or more tables is not fully qualified as the table cannot be found when attempting to EXPLAIN it * When no queries with the specified digest is found during the monitored period These issues have been fixed and a new test case, sysschema.pr_ps_trace_statement_digest, has been added. --- README.md | 8 ++- .../r/pr_ps_trace_statement_digest.result | 30 +++++++++ .../t/pr_ps_trace_statement_digest.test | 65 +++++++++++++++++++ procedures/ps_trace_statement_digest.sql | 53 +++++++++++---- 4 files changed, 142 insertions(+), 14 deletions(-) create mode 100644 mysql-test/suite/sysschema/r/pr_ps_trace_statement_digest.result create mode 100644 mysql-test/suite/sysschema/t/pr_ps_trace_statement_digest.test diff --git a/README.md b/README.md index 4929da5..392a608 100644 --- a/README.md +++ b/README.md @@ -5024,7 +5024,13 @@ When finding a statement of interest within the performance_schema.events_statem It will also attempt to generate an EXPLAIN for the longest running example of the digest during the interval. -Note this may fail, as Performance Schema truncates long SQL_TEXT values (and hence the EXPLAIN will fail due to parse errors). +Note this may fail, as: + +* Performance Schema truncates long SQL_TEXT values (and hence the EXPLAIN will fail due to parse errors) +* the default schema is sys (so tables that are not fully qualified in the query may not be found) +* some queries such as SHOW are not supported in EXPLAIN. + +When the EXPLAIN fails, the error will be ignored and no EXPLAIN output generated. Requires the SUPER privilege for "SET sql_log_bin = 0;". diff --git a/mysql-test/suite/sysschema/r/pr_ps_trace_statement_digest.result b/mysql-test/suite/sysschema/r/pr_ps_trace_statement_digest.result new file mode 100644 index 0000000..4f31b17 --- /dev/null +++ b/mysql-test/suite/sysschema/r/pr_ps_trace_statement_digest.result @@ -0,0 +1,30 @@ +use test; +SET @threadid = sys.ps_thread_id(NULL); +CREATE TABLE t1 (id INT PRIMARY KEY, val int); +INSERT INTO test.t1 VALUES (1, 9); +SET @digest.insert = (SELECT DIGEST FROM performance_schema.events_statements_history WHERE THREAD_ID = @threadid AND SQL_TEXT LIKE 'INSERT INTO test.t1 VALUES (1, 9)'); +SELECT * FROM t1; +id val +1 9 +SET @digest.select = (SELECT DIGEST FROM performance_schema.events_statements_history WHERE THREAD_ID = @threadid AND SQL_TEXT LIKE 'SELECT * FROM t1'); +SHOW CREATE TABLE test.t1; +Table Create Table +t1 CREATE TABLE `t1` ( + `id` int(11) NOT NULL, + `val` int(11) DEFAULT NULL, + PRIMARY KEY (`id`) +) ENGINE=InnoDB DEFAULT CHARSET=latin1 +SET @digest.show = (SELECT DIGEST FROM performance_schema.events_statements_history WHERE THREAD_ID = @threadid AND SQL_TEXT LIKE 'SHOW CREATE TABLE test.t1'); +CREATE SCHEMA test_sys; +use test_sys; +CALL sys.ps_trace_statement_digest(@digest.insert, 0.5, 0.1, FALSE, FALSE); +CALL sys.ps_trace_statement_digest(@digest.select, 0.5, 0.1, FALSE, FALSE); +CALL sys.ps_trace_statement_digest(@digest.show , 0.5, 0.1, FALSE, FALSE); +CALL sys.ps_trace_statement_digest(@digest.insert, 0.5, 0.1, TRUE , FALSE); +use test; +DROP SCHEMA test_sys; +DROP TABLE t1; +SET @threadid = NULL, +@digest.insert = NULL, +@digest.select = NULL, +@digest.show = NULL; diff --git a/mysql-test/suite/sysschema/t/pr_ps_trace_statement_digest.test b/mysql-test/suite/sysschema/t/pr_ps_trace_statement_digest.test new file mode 100644 index 0000000..609c55e --- /dev/null +++ b/mysql-test/suite/sysschema/t/pr_ps_trace_statement_digest.test @@ -0,0 +1,65 @@ +########### suite/sysschema/t/pr_ps_trace_statement_digest.test ############# +# # +# Testing of of the sys.ps_trace_statement_digest() procedure # +# # +# Creation: # +# 2016-06-21 jkrogh Implement this test as part of # +# Bug 23621189 PS_TRACE_STATEMENT_DIGEST FAILS AT EXPLAIN # +# # +############################################################################# + +-- source include/not_embedded.inc +# The ps_trace_statement_digest does not work with prepared statements +# So disable this test with --ps-protocol +-- source include/no_protocol.inc + +use test; + +# Get the thread id of this thread +# Store it in a user variable as otherwise repeated calls to sys.ps_thread_id() +# will keep changing performance_schema.events_statements_history +SET @threadid = sys.ps_thread_id(NULL); + +# Create a table +CREATE TABLE t1 (id INT PRIMARY KEY, val int); + +# Get digest of an INSERT statement with a qualified table name +INSERT INTO test.t1 VALUES (1, 9); +SET @digest.insert = (SELECT DIGEST FROM performance_schema.events_statements_history WHERE THREAD_ID = @threadid AND SQL_TEXT LIKE 'INSERT INTO test.t1 VALUES (1, 9)'); + +# Get digest of an SELECT statement using the default schema +SELECT * FROM t1; +SET @digest.select = (SELECT DIGEST FROM performance_schema.events_statements_history WHERE THREAD_ID = @threadid AND SQL_TEXT LIKE 'SELECT * FROM t1'); + +# Get digets of a SHOW statement (doesn't support EXPLAIN) +SHOW CREATE TABLE test.t1; +SET @digest.show = (SELECT DIGEST FROM performance_schema.events_statements_history WHERE THREAD_ID = @threadid AND SQL_TEXT LIKE 'SHOW CREATE TABLE test.t1'); + +# Don't execute ps_trace_statement_digest() in the same schema as the queries +# to monitor - to ensure we handle queries using the default schema. +CREATE SCHEMA test_sys; +use test_sys; + +# Only do sanity checks - no error should occur, but the actual output is non-deterministic +--disable_result_log +# Regular EXPLAINable SELECT with a qualified table name +CALL sys.ps_trace_statement_digest(@digest.insert, 0.5, 0.1, FALSE, FALSE); +# Table in query is not qualified and is not in the current default schema +CALL sys.ps_trace_statement_digest(@digest.select, 0.5, 0.1, FALSE, FALSE); +# SHOW queries doesn't work with EXPLAIN +CALL sys.ps_trace_statement_digest(@digest.show , 0.5, 0.1, FALSE, FALSE); +# Test that finding no queries works - the TRUE argument resets the P_S tables +# used in ps_trace_statement_digest() +CALL sys.ps_trace_statement_digest(@digest.insert, 0.5, 0.1, TRUE , FALSE); +--enable_result_log + + + +# Clean up +use test; +DROP SCHEMA test_sys; +DROP TABLE t1; +SET @threadid = NULL, + @digest.insert = NULL, + @digest.select = NULL, + @digest.show = NULL; diff --git a/procedures/ps_trace_statement_digest.sql b/procedures/ps_trace_statement_digest.sql index 9f070ee..57cf8df 100644 --- a/procedures/ps_trace_statement_digest.sql +++ b/procedures/ps_trace_statement_digest.sql @@ -1,4 +1,4 @@ --- Copyright (c) 2014, 2015, Oracle and/or its affiliates. All rights reserved. +-- Copyright (c) 2014, 2016, Oracle and/or its affiliates. All rights reserved. -- -- This program is free software; you can redistribute it and/or modify -- it under the terms of the GNU General Public License as published by @@ -39,9 +39,16 @@ CREATE DEFINER='root'@'localhost' PROCEDURE ps_trace_statement_digest ( interval. It will also attempt to generate an EXPLAIN for the longest running - example of the digest during the interval. Note this may fail, as - Performance Schema truncates long SQL_TEXT values (and hence the - EXPLAIN will fail due to parse errors). + example of the digest during the interval. Note this may fail, as: + + * Performance Schema truncates long SQL_TEXT values (and hence the + EXPLAIN will fail due to parse errors) + * the default schema is sys (so tables that are not fully qualified + in the query may not be found) + * some queries such as SHOW are not supported in EXPLAIN. + + When the EXPLAIN fails, the error will be ignored and no EXPLAIN + output generated. Requires the SUPER privilege for "SET sql_log_bin = 0;". @@ -143,6 +150,7 @@ BEGIN DECLARE v_start_fresh BOOLEAN DEFAULT false; DECLARE v_auto_enable BOOLEAN DEFAULT false; + DECLARE v_explain BOOLEAN DEFAULT true; DECLARE v_this_thread_enabed ENUM('YES', 'NO'); DECLARE v_runtime INT DEFAULT 0; DECLARE v_start INT DEFAULT 0; @@ -269,19 +277,38 @@ BEGIN FROM stmt_trace ORDER BY timer_wait DESC LIMIT 1; - SELECT event_name, - sys.format_time(timer_wait) as latency - FROM stmt_stages - WHERE stmt_id = @sql_id - ORDER BY event_id; + IF (@sql_id IS NOT NULL) THEN + SELECT event_name, + sys.format_time(timer_wait) as latency + FROM stmt_stages + WHERE stmt_id = @sql_id + ORDER BY event_id; + END IF; DROP TEMPORARY TABLE stmt_trace; DROP TEMPORARY TABLE stmt_stages; - SET @stmt := CONCAT("EXPLAIN FORMAT=JSON ", @sql); - PREPARE explain_stmt FROM @stmt; - EXECUTE explain_stmt; - DEALLOCATE PREPARE explain_stmt; + IF (@sql IS NOT NULL) THEN + SET @stmt := CONCAT("EXPLAIN FORMAT=JSON ", @sql); + BEGIN + -- Not all queries support EXPLAIN, so catch the cases that are + -- not supported. Currently that includes cases where the table + -- is not fully qualified and is not in the default schema for this + -- procedure as it's not possible to change the default schema inside + -- a procedure. + -- + -- Errno = 1064: You have an error in your SQL syntax + -- Errno = 1146: Table '...' doesn't exist + DECLARE CONTINUE HANDLER FOR 1064, 1146 SET v_explain = false; + + PREPARE explain_stmt FROM @stmt; + END; + + IF (v_explain) THEN + EXECUTE explain_stmt; + DEALLOCATE PREPARE explain_stmt; + END IF; + END IF; IF v_auto_enable THEN CALL sys.ps_setup_reload_saved();