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