1-- Copyright (c) 2014, 2021, Oracle and/or its affiliates. 2-- 3-- This program is free software; you can redistribute it and/or modify 4-- it under the terms of the GNU General Public License, version 2.0, 5-- as published by the Free Software Foundation. 6-- 7-- This program is also distributed with certain software (including 8-- but not limited to OpenSSL) that is licensed under separate terms, 9-- as designated in a particular file or component or in included license 10-- documentation. The authors of MySQL hereby grant you an additional 11-- permission to link the program and your derivative works with the 12-- separately licensed software that they have included with MySQL. 13-- 14-- This program is distributed in the hope that it will be useful, 15-- but WITHOUT ANY WARRANTY; without even the implied warranty of 16-- MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the 17-- GNU General Public License, version 2.0, for more details. 18-- 19-- You should have received a copy of the GNU General Public License 20-- along with this program; if not, write to the Free Software 21-- Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA 22 23DROP PROCEDURE IF EXISTS ps_trace_statement_digest; 24 25DELIMITER $$ 26 27CREATE DEFINER='mysql.sys'@'localhost' PROCEDURE ps_trace_statement_digest ( 28 IN in_digest VARCHAR(32), 29 IN in_runtime INT, 30 IN in_interval DECIMAL(2,2), 31 IN in_start_fresh BOOLEAN, 32 IN in_auto_enable BOOLEAN 33 ) 34 COMMENT ' 35Description 36----------- 37 38Traces all instrumentation within Performance Schema for a specific 39Statement Digest. 40 41When finding a statement of interest within the 42performance_schema.events_statements_summary_by_digest table, feed 43the DIGEST MD5 value in to this procedure, set how long to poll for, 44and at what interval to poll, and it will generate a report of all 45statistics tracked within Performance Schema for that digest for the 46interval. 47 48It will also attempt to generate an EXPLAIN for the longest running 49example of the digest during the interval. Note this may fail, as: 50 51 * Performance Schema truncates long SQL_TEXT values (and hence the 52 EXPLAIN will fail due to parse errors) 53 * the default schema is sys (so tables that are not fully qualified 54 in the query may not be found) 55 * some queries such as SHOW are not supported in EXPLAIN. 56 57When the EXPLAIN fails, the error will be ignored and no EXPLAIN 58output generated. 59 60Requires the SUPER privilege for "SET sql_log_bin = 0;". 61 62Parameters 63----------- 64 65in_digest (VARCHAR(32)): 66 The statement digest identifier you would like to analyze 67in_runtime (INT): 68 The number of seconds to run analysis for 69in_interval (DECIMAL(2,2)): 70 The interval (in seconds, may be fractional) at which to try 71 and take snapshots 72in_start_fresh (BOOLEAN): 73 Whether to TRUNCATE the events_statements_history_long and 74 events_stages_history_long tables before starting 75in_auto_enable (BOOLEAN): 76 Whether to automatically turn on required consumers 77 78Example 79----------- 80 81mysql> call ps_trace_statement_digest(\'891ec6860f98ba46d89dd20b0c03652c\', 10, 0.1, true, true); 82+--------------------+ 83| SUMMARY STATISTICS | 84+--------------------+ 85| SUMMARY STATISTICS | 86+--------------------+ 871 row in set (9.11 sec) 88 89+------------+-----------+-----------+-----------+---------------+------------+------------+ 90| executions | exec_time | lock_time | rows_sent | rows_examined | tmp_tables | full_scans | 91+------------+-----------+-----------+-----------+---------------+------------+------------+ 92| 21 | 4.11 ms | 2.00 ms | 0 | 21 | 0 | 0 | 93+------------+-----------+-----------+-----------+---------------+------------+------------+ 941 row in set (9.11 sec) 95 96+------------------------------------------+-------+-----------+ 97| event_name | count | latency | 98+------------------------------------------+-------+-----------+ 99| stage/sql/checking query cache for query | 16 | 724.37 us | 100| stage/sql/statistics | 16 | 546.92 us | 101| stage/sql/freeing items | 18 | 520.11 us | 102| stage/sql/init | 51 | 466.80 us | 103... 104| stage/sql/cleaning up | 18 | 11.92 us | 105| stage/sql/executing | 16 | 6.95 us | 106+------------------------------------------+-------+-----------+ 10717 rows in set (9.12 sec) 108 109+---------------------------+ 110| LONGEST RUNNING STATEMENT | 111+---------------------------+ 112| LONGEST RUNNING STATEMENT | 113+---------------------------+ 1141 row in set (9.16 sec) 115 116+-----------+-----------+-----------+-----------+---------------+------------+-----------+ 117| thread_id | exec_time | lock_time | rows_sent | rows_examined | tmp_tables | full_scan | 118+-----------+-----------+-----------+-----------+---------------+------------+-----------+ 119| 166646 | 618.43 us | 1.00 ms | 0 | 1 | 0 | 0 | 120+-----------+-----------+-----------+-----------+---------------+------------+-----------+ 1211 row in set (9.16 sec) 122 123// Truncated for clarity... 124+-----------------------------------------------------------------+ 125| sql_text | 126+-----------------------------------------------------------------+ 127| select hibeventhe0_.id as id1382_, hibeventhe0_.createdTime ... | 128+-----------------------------------------------------------------+ 1291 row in set (9.17 sec) 130 131+------------------------------------------+-----------+ 132| event_name | latency | 133+------------------------------------------+-----------+ 134| stage/sql/init | 8.61 us | 135| stage/sql/Waiting for query cache lock | 453.23 us | 136| stage/sql/init | 331.07 ns | 137| stage/sql/checking query cache for query | 43.04 us | 138... 139| stage/sql/freeing items | 30.46 us | 140| stage/sql/cleaning up | 662.13 ns | 141+------------------------------------------+-----------+ 14218 rows in set (9.23 sec) 143 144+----+-------------+--------------+-------+---------------+-----------+---------+-------------+------+-------+ 145| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | 146+----+-------------+--------------+-------+---------------+-----------+---------+-------------+------+-------+ 147| 1 | SIMPLE | hibeventhe0_ | const | fixedTime | fixedTime | 775 | const,const | 1 | NULL | 148+----+-------------+--------------+-------+---------------+-----------+---------+-------------+------+-------+ 1491 row in set (9.27 sec) 150 151Query OK, 0 rows affected (9.28 sec) 152' 153 SQL SECURITY INVOKER 154 NOT DETERMINISTIC 155 MODIFIES SQL DATA 156BEGIN 157 158 DECLARE v_start_fresh BOOLEAN DEFAULT false; 159 DECLARE v_auto_enable BOOLEAN DEFAULT false; 160 DECLARE v_explain BOOLEAN DEFAULT true; 161 DECLARE v_this_thread_enabed ENUM('YES', 'NO'); 162 DECLARE v_runtime INT DEFAULT 0; 163 DECLARE v_start INT DEFAULT 0; 164 DECLARE v_found_stmts INT; 165 166 SET @log_bin := @@sql_log_bin; 167 SET sql_log_bin = 0; 168 169 -- Do not track the current thread, it will kill the stack 170 SELECT INSTRUMENTED INTO v_this_thread_enabed FROM performance_schema.threads WHERE PROCESSLIST_ID = CONNECTION_ID(); 171 CALL sys.ps_setup_disable_thread(CONNECTION_ID()); 172 173 DROP TEMPORARY TABLE IF EXISTS stmt_trace; 174 CREATE TEMPORARY TABLE stmt_trace ( 175 thread_id BIGINT UNSIGNED, 176 timer_start BIGINT UNSIGNED, 177 event_id BIGINT UNSIGNED, 178 sql_text longtext, 179 timer_wait BIGINT UNSIGNED, 180 lock_time BIGINT UNSIGNED, 181 errors BIGINT UNSIGNED, 182 mysql_errno INT, 183 rows_sent BIGINT UNSIGNED, 184 rows_affected BIGINT UNSIGNED, 185 rows_examined BIGINT UNSIGNED, 186 created_tmp_tables BIGINT UNSIGNED, 187 created_tmp_disk_tables BIGINT UNSIGNED, 188 no_index_used BIGINT UNSIGNED, 189 PRIMARY KEY (thread_id, timer_start) 190 ); 191 192 DROP TEMPORARY TABLE IF EXISTS stmt_stages; 193 CREATE TEMPORARY TABLE stmt_stages ( 194 event_id BIGINT UNSIGNED, 195 stmt_id BIGINT UNSIGNED, 196 event_name VARCHAR(128), 197 timer_wait BIGINT UNSIGNED, 198 PRIMARY KEY (event_id) 199 ); 200 201 SET v_start_fresh = in_start_fresh; 202 IF v_start_fresh THEN 203 TRUNCATE TABLE performance_schema.events_statements_history_long; 204 TRUNCATE TABLE performance_schema.events_stages_history_long; 205 END IF; 206 207 SET v_auto_enable = in_auto_enable; 208 IF v_auto_enable THEN 209 CALL sys.ps_setup_save(0); 210 211 UPDATE performance_schema.threads 212 SET INSTRUMENTED = IF(PROCESSLIST_ID IS NOT NULL, 'YES', 'NO'); 213 214 -- Only the events_statements_history_long and events_stages_history_long tables and their ancestors are needed 215 UPDATE performance_schema.setup_consumers 216 SET ENABLED = 'YES' 217 WHERE NAME NOT LIKE '%\_history' 218 AND NAME NOT LIKE 'events_wait%' 219 AND NAME NOT LIKE 'events_transactions%' 220 AND NAME <> 'statements_digest'; 221 222 UPDATE performance_schema.setup_instruments 223 SET ENABLED = 'YES', 224 TIMED = 'YES' 225 WHERE NAME LIKE 'statement/%' OR NAME LIKE 'stage/%'; 226 END IF; 227 228 WHILE v_runtime < in_runtime DO 229 SELECT UNIX_TIMESTAMP() INTO v_start; 230 231 INSERT IGNORE INTO stmt_trace 232 SELECT thread_id, timer_start, event_id, sql_text, timer_wait, lock_time, errors, mysql_errno, 233 rows_sent, rows_affected, rows_examined, created_tmp_tables, created_tmp_disk_tables, no_index_used 234 FROM performance_schema.events_statements_history_long 235 WHERE digest = in_digest; 236 237 INSERT IGNORE INTO stmt_stages 238 SELECT stages.event_id, stmt_trace.event_id, 239 stages.event_name, stages.timer_wait 240 FROM performance_schema.events_stages_history_long AS stages 241 JOIN stmt_trace ON stages.nesting_event_id = stmt_trace.event_id; 242 243 SELECT SLEEP(in_interval) INTO @sleep; 244 SET v_runtime = v_runtime + (UNIX_TIMESTAMP() - v_start); 245 END WHILE; 246 247 SELECT "SUMMARY STATISTICS"; 248 249 SELECT COUNT(*) executions, 250 sys.format_time(SUM(timer_wait)) AS exec_time, 251 sys.format_time(SUM(lock_time)) AS lock_time, 252 SUM(rows_sent) AS rows_sent, 253 SUM(rows_affected) AS rows_affected, 254 SUM(rows_examined) AS rows_examined, 255 SUM(created_tmp_tables) AS tmp_tables, 256 SUM(no_index_used) AS full_scans 257 FROM stmt_trace; 258 259 SELECT event_name, 260 COUNT(*) as count, 261 sys.format_time(SUM(timer_wait)) as latency 262 FROM stmt_stages 263 GROUP BY event_name 264 ORDER BY SUM(timer_wait) DESC; 265 266 SELECT "LONGEST RUNNING STATEMENT"; 267 268 SELECT thread_id, 269 sys.format_time(timer_wait) AS exec_time, 270 sys.format_time(lock_time) AS lock_time, 271 rows_sent, 272 rows_affected, 273 rows_examined, 274 created_tmp_tables AS tmp_tables, 275 no_index_used AS full_scan 276 FROM stmt_trace 277 ORDER BY timer_wait DESC LIMIT 1; 278 279 SELECT sql_text 280 FROM stmt_trace 281 ORDER BY timer_wait DESC LIMIT 1; 282 283 SELECT sql_text, event_id INTO @sql, @sql_id 284 FROM stmt_trace 285 ORDER BY timer_wait DESC LIMIT 1; 286 287 IF (@sql_id IS NOT NULL) THEN 288 SELECT event_name, 289 sys.format_time(timer_wait) as latency 290 FROM stmt_stages 291 WHERE stmt_id = @sql_id 292 ORDER BY event_id; 293 END IF; 294 295 DROP TEMPORARY TABLE stmt_trace; 296 DROP TEMPORARY TABLE stmt_stages; 297 298 IF (@sql IS NOT NULL) THEN 299 SET @stmt := CONCAT("EXPLAIN FORMAT=JSON ", @sql); 300 BEGIN 301 -- Not all queries support EXPLAIN, so catch the cases that are 302 -- not supported. Currently that includes cases where the table 303 -- is not fully qualified and is not in the default schema for this 304 -- procedure as it's not possible to change the default schema inside 305 -- a procedure. 306 -- 307 -- Errno = 1064: You have an error in your SQL syntax 308 -- Errno = 1146: Table '...' doesn't exist 309 DECLARE CONTINUE HANDLER FOR 1064, 1146 SET v_explain = false; 310 311 PREPARE explain_stmt FROM @stmt; 312 END; 313 314 IF (v_explain) THEN 315 EXECUTE explain_stmt; 316 DEALLOCATE PREPARE explain_stmt; 317 END IF; 318 END IF; 319 320 IF v_auto_enable THEN 321 CALL sys.ps_setup_reload_saved(); 322 END IF; 323 -- Restore INSTRUMENTED for this thread 324 IF (v_this_thread_enabed = 'YES') THEN 325 CALL sys.ps_setup_enable_thread(CONNECTION_ID()); 326 END IF; 327 328 SET sql_log_bin = @log_bin; 329END$$ 330 331DELIMITER ; 332