-
Notifications
You must be signed in to change notification settings - Fork 111
ps_trace_statement_digest()
xiaoboluo768 edited this page Jun 9, 2020
·
3 revisions
-
用于Trace给定digest值（第一个传参）的语句的Performance Schema监控过程，根据传入的采集时间和采集间隔（第二第三传参），定期从events_statements_history_long和events_stages_history_long表中采集数据，分别创建两张临时表stmt_trace、stmt_stages，从两张consumers表中使用insert ... select...语句分别插入两张临时表，每个采集间隔时间操作一次该语句，然后通过查询各种统计聚合要求从这两张表中执行查询并打印，期间会关闭后台线程和执行该存储过程调用的线程的instruments采集和binlog记录功能(需要SUPER权限)，第四个传参控制是否在执行trace数据收集前清空两个历史事件记录表，第五个传参控制是否自动开启需要的consumers表
- 如果在performance_schema.events_statements_summary_by_digest表找到了你想要执行追踪分析的语句，可以通过调用该存储过程传入其语句的DIGEST列值，并指定执行追踪时长和间隔，执行完成之后会打印该语句的相关统计信息报告
- 该存储过程还会尝试执行EXPLAIN操作，但此尝试可能会失败，因为超长的SQL语句可能在存入events_statements_summary_by_digest表时已经被截断了
-
参数：
- in_digest VARCHAR（32）：要追踪分析的语句在events_statements_summary_by_digest表中的DIGEST列值
- in_runtime INT：该语句需要追踪收集多长时间的数据，单位秒
- in_interval DECIMAL（2,2）：在追踪收集期间尝试拍摄快照(其实就是执行一次从两个历史表查询数据并写入查询数据到临时表的操作)的分析间隔时间（以秒为单位，值可以是小数）
- in_start_fresh BOOLEAN：是否在该存储过程开始执行之前清空performance_schema下的events_statements_history_long和events_stages_history_long表
- in_auto_enable BOOLEAN：是否自动启用所需的配置(如果没有开启对应的配置，则会在threads、setup_consumers、setup_instruments表中自动对所需要的配置进行开启，在执行结束时自动恢复配置)，注意：如果是执行该存储过程时才开启，对应的consumers表中可能没有指定语句的数据，所以，你最好提前单独开启'%_history'、'events_wait%'、 'events_transactions%'的consumers配置，'statement/%' 、'stage/%'的instruments配置，开启对应的线程监控配置
-
定义语句
DROP PROCEDURE IF EXISTS ps_trace_statement_digest;
DELIMITER $$
CREATE DEFINER='root'@'localhost' PROCEDURE ps_trace_statement_digest (
IN in_digest VARCHAR(32),
IN in_runtime INT,
IN in_interval DECIMAL(2,2),
IN in_start_fresh BOOLEAN,
IN in_auto_enable BOOLEAN
)
COMMENT '
Description
-----------
Traces all instrumentation within Performance Schema for a specific
Statement Digest.
When finding a statement of interest within the
performance_schema.events_statements_summary_by_digest table, feed
the DIGEST MD5 value in to this procedure, set how long to poll for,
and at what interval to poll, and it will generate a report of all
statistics tracked within Performance Schema for that digest for the
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)
* 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;".
Parameters
-----------
in_digest (VARCHAR(32)):
The statement digest identifier you would like to analyze
in_runtime (INT):
The number of seconds to run analysis for
in_interval (DECIMAL(2,2)):
The interval (in seconds, may be fractional) at which to try
and take snapshots
in_start_fresh (BOOLEAN):
Whether to TRUNCATE the events_statements_history_long and
events_stages_history_long tables before starting
in_auto_enable (BOOLEAN):
Whether to automatically turn on required consumers
Example
-----------
mysql> call ps_trace_statement_digest(\'891ec6860f98ba46d89dd20b0c03652c\', 10, 0.1, true, true);
+--------------------+
| SUMMARY STATISTICS |
+--------------------+
| SUMMARY STATISTICS |
+--------------------+
1 row in set (9.11 sec)
+------------+-----------+-----------+-----------+---------------+------------+------------+
| executions | exec_time | lock_time | rows_sent | rows_examined | tmp_tables | full_scans |
+------------+-----------+-----------+-----------+---------------+------------+------------+
| 21 | 4.11 ms | 2.00 ms | 0 | 21 | 0 | 0 |
+------------+-----------+-----------+-----------+---------------+------------+------------+
1 row in set (9.11 sec)
+------------------------------------------+-------+-----------+
| event_name | count | latency |
+------------------------------------------+-------+-----------+
| stage/sql/checking query cache for query | 16 | 724.37 us |
| stage/sql/statistics | 16 | 546.92 us |
| stage/sql/freeing items | 18 | 520.11 us |
| stage/sql/init | 51 | 466.80 us |
...
| stage/sql/cleaning up | 18 | 11.92 us |
| stage/sql/executing | 16 | 6.95 us |
+------------------------------------------+-------+-----------+
17 rows in set (9.12 sec)
+---------------------------+
| LONGEST RUNNING STATEMENT |
+---------------------------+
| LONGEST RUNNING STATEMENT |
+---------------------------+
1 row in set (9.16 sec)
+-----------+-----------+-----------+-----------+---------------+------------+-----------+
| thread_id | exec_time | lock_time | rows_sent | rows_examined | tmp_tables | full_scan |
+-----------+-----------+-----------+-----------+---------------+------------+-----------+
| 166646 | 618.43 us | 1.00 ms | 0 | 1 | 0 | 0 |
+-----------+-----------+-----------+-----------+---------------+------------+-----------+
1 row in set (9.16 sec)
// Truncated for clarity...
+-----------------------------------------------------------------+
| sql_text |
+-----------------------------------------------------------------+
| select hibeventhe0_.id as id1382_, hibeventhe0_.createdTime ... |
+-----------------------------------------------------------------+
1 row in set (9.17 sec)
+------------------------------------------+-----------+
| event_name | latency |
+------------------------------------------+-----------+
| stage/sql/init | 8.61 us |
| stage/sql/Waiting for query cache lock | 453.23 us |
| stage/sql/init | 331.07 ns |
| stage/sql/checking query cache for query | 43.04 us |
...
| stage/sql/freeing items | 30.46 us |
| stage/sql/cleaning up | 662.13 ns |
+------------------------------------------+-----------+
18 rows in set (9.23 sec)
+----+-------------+--------------+-------+---------------+-----------+---------+-------------+------+-------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+--------------+-------+---------------+-----------+---------+-------------+------+-------+
| 1 | SIMPLE | hibeventhe0_ | const | fixedTime | fixedTime | 775 | const,const | 1 | NULL |
+----+-------------+--------------+-------+---------------+-----------+---------+-------------+------+-------+
1 row in set (9.27 sec)
Query OK, 0 rows affected (9.28 sec)
'
SQL SECURITY INVOKER
NOT DETERMINISTIC
MODIFIES SQL DATA
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;
DECLARE v_found_stmts INT;
SET @log_bin := @@sql_log_bin;
SET sql_log_bin = 0;
-- Do not track the current thread, it will kill the stack
SELECT INSTRUMENTED INTO v_this_thread_enabed FROM performance_schema.threads WHERE PROCESSLIST_ID = CONNECTION_ID();
CALL sys.ps_setup_disable_thread(CONNECTION_ID());
DROP TEMPORARY TABLE IF EXISTS stmt_trace;
CREATE TEMPORARY TABLE stmt_trace (
thread_id BIGINT UNSIGNED,
timer_start BIGINT UNSIGNED,
event_id BIGINT UNSIGNED,
sql_text longtext,
timer_wait BIGINT UNSIGNED,
lock_time BIGINT UNSIGNED,
errors BIGINT UNSIGNED,
mysql_errno INT,
rows_sent BIGINT UNSIGNED,
rows_affected BIGINT UNSIGNED,
rows_examined BIGINT UNSIGNED,
created_tmp_tables BIGINT UNSIGNED,
created_tmp_disk_tables BIGINT UNSIGNED,
no_index_used BIGINT UNSIGNED,
PRIMARY KEY (thread_id, timer_start)
);
DROP TEMPORARY TABLE IF EXISTS stmt_stages;
CREATE TEMPORARY TABLE stmt_stages (
event_id BIGINT UNSIGNED,
stmt_id BIGINT UNSIGNED,
event_name VARCHAR(128),
timer_wait BIGINT UNSIGNED,
PRIMARY KEY (event_id)
);
SET v_start_fresh = in_start_fresh;
IF v_start_fresh THEN
TRUNCATE TABLE performance_schema.events_statements_history_long;
TRUNCATE TABLE performance_schema.events_stages_history_long;
END IF;
SET v_auto_enable = in_auto_enable;
IF v_auto_enable THEN
CALL sys.ps_setup_save(0);
UPDATE performance_schema.threads
SET INSTRUMENTED = IF(PROCESSLIST_ID IS NOT NULL, 'YES', 'NO');
-- Only the events_statements_history_long and events_stages_history_long tables and their ancestors are needed
UPDATE performance_schema.setup_consumers
SET ENABLED = 'YES'
WHERE NAME NOT LIKE '%\_history'
AND NAME NOT LIKE 'events_wait%'
AND NAME NOT LIKE 'events_transactions%'
AND NAME <> 'statements_digest';
UPDATE performance_schema.setup_instruments
SET ENABLED = 'YES',
TIMED = 'YES'
WHERE NAME LIKE 'statement/%' OR NAME LIKE 'stage/%';
END IF;
WHILE v_runtime < in_runtime DO
SELECT UNIX_TIMESTAMP() INTO v_start;
INSERT IGNORE INTO stmt_trace
SELECT thread_id, timer_start, event_id, sql_text, timer_wait, lock_time, errors, mysql_errno,
rows_sent, rows_affected, rows_examined, created_tmp_tables, created_tmp_disk_tables, no_index_used
FROM performance_schema.events_statements_history_long
WHERE digest = in_digest;
INSERT IGNORE INTO stmt_stages
SELECT stages.event_id, stmt_trace.event_id,
stages.event_name, stages.timer_wait
FROM performance_schema.events_stages_history_long AS stages
JOIN stmt_trace ON stages.nesting_event_id = stmt_trace.event_id;
SELECT SLEEP(in_interval) INTO @sleep;
SET v_runtime = v_runtime + (UNIX_TIMESTAMP() - v_start);
END WHILE;
SELECT "SUMMARY STATISTICS";
SELECT COUNT(*) executions,
sys.format_time(SUM(timer_wait)) AS exec_time,
sys.format_time(SUM(lock_time)) AS lock_time,
SUM(rows_sent) AS rows_sent,
SUM(rows_affected) AS rows_affected,
SUM(rows_examined) AS rows_examined,
SUM(created_tmp_tables) AS tmp_tables,
SUM(no_index_used) AS full_scans
FROM stmt_trace;
SELECT event_name,
COUNT(*) as count,
sys.format_time(SUM(timer_wait)) as latency
FROM stmt_stages
GROUP BY event_name
ORDER BY SUM(timer_wait) DESC;
SELECT "LONGEST RUNNING STATEMENT";
SELECT thread_id,
sys.format_time(timer_wait) AS exec_time,
sys.format_time(lock_time) AS lock_time,
rows_sent,
rows_affected,
rows_examined,
created_tmp_tables AS tmp_tables,
no_index_used AS full_scan
FROM stmt_trace
ORDER BY timer_wait DESC LIMIT 1;
SELECT sql_text
FROM stmt_trace
ORDER BY timer_wait DESC LIMIT 1;
SELECT sql_text, event_id INTO @sql, @sql_id
FROM stmt_trace
ORDER BY timer_wait DESC LIMIT 1;
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;
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();
END IF;
-- Restore INSTRUMENTED for this thread
IF (v_this_thread_enabed = 'YES') THEN
CALL sys.ps_setup_enable_thread(CONNECTION_ID());
END IF;
SET sql_log_bin = @log_bin;
END$$
DELIMITER ;
- 示例
# 会话一执行存储过程
root@localhost : sys 10:23:17> select DIGEST from performance_schema.events_statements_summary_by_digest where SCHEMA_NAME is not null and DIGEST_TEXT regexp 'delete|select|update|insert|alter' \
order by COUNT_STAR desc limit 1 into @x;
Query OK, 1 row affected (0.00 sec)
root@localhost : sys 10:23:21> call ps_trace_statement_digest(@x,10,0.1,true,true);
+-------------------+
| summary |
+-------------------+
| Disabled 1 thread |
+-------------------+
1 row in set (0.01 sec)
# 会话二执行对应的语句（注意：这里是手工传入digest值，该存储过程可能更多时候用于嵌套在其他存储过程中查询某个资源消耗最多的SQL的digest）
root@localhost : luoxiaobo 10:26:15> select * from t_luoxiaobo limit 100; #这里执行了10次
+-----+------+---------------------+-------+
| id | test | datet_time | test1 |
+-----+------+---------------------+-------+
| 5 | 1 | 2017-07-04 00:13:14 | NULL |
| 7 | 2 | 2017-07-04 00:13:14 | NULL |
......
# 回到会话一 10秒后查看结果
......
+--------------------+
| SUMMARY STATISTICS |
+--------------------+
| SUMMARY STATISTICS |
+--------------------+
1 row in set (9.91 sec)
+------------+-----------+-----------+-----------+---------------+---------------+------------+------------+
| executions | exec_time | lock_time | rows_sent | rows_affected | rows_examined | tmp_tables | full_scans |
+------------+-----------+-----------+-----------+---------------+---------------+------------+------------+
| 7 | 1.38 ms | 488.00 us | 700 | 0 | 700 | 0 | 7 |
+------------+-----------+-----------+-----------+---------------+---------------+------------+------------+
1 row in set (9.93 sec)
+--------------------------------+-------+-----------+
| event_name | count | latency |
+--------------------------------+-------+-----------+
| stage/sql/Sending data | 7 | 532.58 us |
| stage/sql/starting | 6 | 279.46 us |
| stage/sql/init | 7 | 93.88 us |
| stage/sql/Opening tables | 7 | 70.64 us |
| stage/sql/query end | 7 | 53.42 us |
| stage/sql/preparing | 7 | 50.81 us |
| stage/sql/statistics | 7 | 45.71 us |
| stage/sql/freeing items | 6 | 45.26 us |
| stage/sql/checking permissions | 9 | 36.30 us |
| stage/sql/System lock | 7 | 34.39 us |
| stage/sql/closing tables | 7 | 22.69 us |
| stage/sql/optimizing | 7 | 18.91 us |
| stage/sql/end | 7 | 4.35 us |
| stage/sql/cleaning up | 7 | 3.04 us |
| stage/sql/executing | 7 | 1.41 us |
+--------------------------------+-------+-----------+
15 rows in set (9.93 sec)
+---------------------------+
| LONGEST RUNNING STATEMENT |
+---------------------------+
| LONGEST RUNNING STATEMENT |
+---------------------------+
1 row in set (9.93 sec)
+-----------+-----------+-----------+-----------+---------------+---------------+------------+-----------+
| thread_id | exec_time | lock_time | rows_sent | rows_affected | rows_examined | tmp_tables | full_scan |
+-----------+-----------+-----------+-----------+---------------+---------------+------------+-----------+
| 48 | 344.39 us | 114.00 us | 100 | 0 | 100 | 0 | 1 |
+-----------+-----------+-----------+-----------+---------------+---------------+------------+-----------+
1 row in set (9.93 sec)
+-------------------------------------+
| sql_text |
+-------------------------------------+
| select * from t_luoxiaobo limit 100 |
+-------------------------------------+
1 row in set (9.93 sec)
+--------------------------------+-----------+
| event_name | latency |
+--------------------------------+-----------+
| stage/sql/starting | 75.62 us |
| stage/sql/checking permissions | 12.90 us |
| stage/sql/Opening tables | 19.51 us |
| stage/sql/init | 20.83 us |
| stage/sql/System lock | 13.88 us |
| stage/sql/optimizing | 993.00 ns |
| stage/sql/statistics | 6.74 us |
| stage/sql/preparing | 16.79 us |
| stage/sql/executing | 269.00 ns |
| stage/sql/Sending data | 148.06 us |
| stage/sql/end | 716.00 ns |
| stage/sql/query end | 15.88 us |
| stage/sql/closing tables | 3.48 us |
| stage/sql/freeing items | 7.28 us |
| stage/sql/cleaning up | 456.00 ns |
+--------------------------------+-----------+
15 rows in set (9.93 sec)
+------------------+
| summary |
+------------------+
| Enabled 1 thread |
+------------------+
1 row in set (10.17 sec)
Query OK, 0 rows affected (10.17 sec)
上一篇： ps_statement_avg_latency_histogram()存储过程 | 下一篇： ps_trace_thread()存储过程
- 验证、测试、整理：罗小波
- QQ：309969177
- 提示：本系列文章的主体结构遵循Oracle MySQL 官方 5.7 手册中，关于information_schema、mysql schema、performance_schema、sys schema的章节结构体系，并额外添加了一些验证、测试数据。鉴于本人精力和能力有限，难免出现一些纰漏，欢迎大家踊跃指正！