Bug #23621189 PS_TRACE_STATEMENT_DIGEST FAILS AT EXPLAIN OR NO FOUND QUERIES

JesperWisborgKrogh · JesperWisborgKrogh · commit 76b512c7a03a · 2016-06-21T22:34:07.000+10:00
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.
diff --git 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
@@ -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
@@ -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
@@ -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();
