ps_trace_thread()
-
用于trace只指定线程ID的事件信息，一共7个传参，第一个为线程ID，第二个为打印信息输出文件路径(该存储过程可以把监控线程的性能数据导出到一个.dot格式文件中，记录格式为用于生成图形的描述语言)，第三个为收集数据最大时长（指定Null默认为60秒），第四个为采集间隔(指定null默认为1秒)，第五个为在执行数据收集之前是否清空所有performance_schema历史事件数据，第六个为是否关闭除了自己外的其他线程及其开启所有的instruments和consumers，第七个为是否打印event_name对应的源文件和代码行号，最后会打印dot转换为PDF和PNG的命令（注：dot命令为graphviz的rpm包安装），dot命令会为每条sql语句生成一个资源消耗树
- 查询wait、stage、statuments、transaction几个事件类型的history_long表保存到临时表tmp_events中(按照第四个传参间隔采集)，然后使用select查询tmp_events临时数据表输出到第二个传参指定的文件中，然后删除临时表
- 如果第六个传参为TRUE，则在修改配置前会调用sys.ps_setup_save(0);保存配置到临时表，数据收集完成之后会调用CALL sys.ps_setup_reload_saved();从临时表中恢复配置表
- 此存储过程需要SUPER权限，因为它会在执行期间会话级别关闭sql_log_bin系统变量禁用二进制日志记录功能，另外，还需要FILE权限，执行过程中的数据会写入到一个文件dot格式文件中保存
-
参数：
- in_thread_id INT：要跟踪的线程ID，注意：这是内部线程ID，不是进程ID
- in_outfile VARCHAR（255）：导出的.dot输出文件的路径和名称
- in_max_runtime DECIMAL（20,2）：收集数据的最大时长（单位秒，可以是小数），如果使用NULL值，则存储过程会使用默认值60秒
- in_interval DECIMAL（20,2）：收集数据的间隔时长（单位秒，可以是分数），如果使用NULL值，则存储过程会使用默认值1秒
- in_start_fresh BOOLEAN：是否在执行数据收集之前清空所有的performance_schema数据
- in_auto_setup BOOLEAN：是否在执行数据收集之前禁用所有其他线程并启用所有instruments和consumers，注意：虽然在存储过程执行完成时会还原配置，但是开启所有的instruments和consumers会明显拉低性能，除非必须，否则不建议使用TRUE值
- in_debug BOOLEAN：是否在执行数据收集时同时输出instruments所在的文件名和代码行号信息
-
定义语句
DROP PROCEDURE IF EXISTS ps_trace_thread;
DELIMITER $$
CREATE DEFINER='root'@'localhost' PROCEDURE ps_trace_thread (
IN in_thread_id BIGINT UNSIGNED,
IN in_outfile VARCHAR(255),
IN in_max_runtime DECIMAL(20,2),
IN in_interval DECIMAL(20,2),
IN in_start_fresh BOOLEAN,
IN in_auto_setup BOOLEAN,
IN in_debug BOOLEAN
)
COMMENT '
Description
-----------
Dumps all data within Performance Schema for an instrumented thread,
to create a DOT formatted graph file.
Each resultset returned from the procedure should be used for a complete graph
Requires the SUPER privilege for "SET sql_log_bin = 0;".
Parameters
-----------
in_thread_id (BIGINT UNSIGNED):
The thread that you would like a stack trace for
in_outfile (VARCHAR(255)):
The filename the dot file will be written to
in_max_runtime (DECIMAL(20,2)):
The maximum time to keep collecting data.
Use NULL to get the default which is 60 seconds.
in_interval (DECIMAL(20,2)):
How long to sleep between data collections.
Use NULL to get the default which is 1 second.
in_start_fresh (BOOLEAN):
Whether to reset all Performance Schema data before tracing.
in_auto_setup (BOOLEAN):
Whether to disable all other threads and enable all consumers/instruments.
This will also reset the settings at the end of the run.
in_debug (BOOLEAN):
Whether you would like to include file:lineno in the graph
Example
-----------
mysql> CALL sys.ps_trace_thread(25, CONCAT(\'/tmp/stack-\', REPLACE(NOW(), \' \', \'-\'), \'.dot\'), NULL, NULL, TRUE, TRUE, TRUE);
+-------------------+
| summary |
+-------------------+
| Disabled 1 thread |
+-------------------+
1 row in set (0.00 sec)
+---------------------------------------------+
| Info |
+---------------------------------------------+
| Data collection starting for THREAD_ID = 25 |
+---------------------------------------------+
1 row in set (0.03 sec)
+-----------------------------------------------------------+
| Info |
+-----------------------------------------------------------+
| Stack trace written to /tmp/stack-2014-02-16-21:18:41.dot |
+-----------------------------------------------------------+
1 row in set (60.07 sec)
+-------------------------------------------------------------------+
| Convert to PDF |
+-------------------------------------------------------------------+
| dot -Tpdf -o /tmp/stack_25.pdf /tmp/stack-2014-02-16-21:18:41.dot |
+-------------------------------------------------------------------+
1 row in set (60.07 sec)
+-------------------------------------------------------------------+
| Convert to PNG |
+-------------------------------------------------------------------+
| dot -Tpng -o /tmp/stack_25.png /tmp/stack-2014-02-16-21:18:41.dot |
+-------------------------------------------------------------------+
1 row in set (60.07 sec)
+------------------+
| summary |
+------------------+
| Enabled 1 thread |
+------------------+
1 row in set (60.32 sec)
'
SQL SECURITY INVOKER
NOT DETERMINISTIC
MODIFIES SQL DATA
BEGIN
DECLARE v_done bool DEFAULT FALSE;
DECLARE v_start, v_runtime DECIMAL(20,2) DEFAULT 0.0;
DECLARE v_min_event_id bigint unsigned DEFAULT 0;
DECLARE v_this_thread_enabed ENUM('YES', 'NO');
DECLARE v_event longtext;
DECLARE c_stack CURSOR FOR
SELECT CONCAT(IF(nesting_event_id IS NOT NULL, CONCAT(nesting_event_id, ' -> '), ''),
event_id, '; ', event_id, ' [label="',
-- Convert from picoseconds to microseconds
'(', sys.format_time(timer_wait), ') ',
IF (event_name NOT LIKE 'wait/io%',
SUBSTRING_INDEX(event_name, '/', -2),
IF (event_name NOT LIKE 'wait/io/file%' OR event_name NOT LIKE 'wait/io/socket%',
SUBSTRING_INDEX(event_name, '/', -4),
event_name)
),
-- Always dump the extra wait information gathered for transactions and statements
IF (event_name LIKE 'transaction', IFNULL(CONCAT('\\n', wait_info), ''), ''),
IF (event_name LIKE 'statement/%', IFNULL(CONCAT('\\n', wait_info), ''), ''),
-- If debug is enabled, add the file:lineno information for waits
IF (in_debug AND event_name LIKE 'wait%', wait_info, ''),
'", ',
-- Depending on the type of event, style appropriately
CASE WHEN event_name LIKE 'wait/io/file%' THEN
'shape=box, style=filled, color=red'
WHEN event_name LIKE 'wait/io/table%' THEN
'shape=box, style=filled, color=green'
WHEN event_name LIKE 'wait/io/socket%' THEN
'shape=box, style=filled, color=yellow'
WHEN event_name LIKE 'wait/synch/mutex%' THEN
'style=filled, color=lightskyblue'
WHEN event_name LIKE 'wait/synch/cond%' THEN
'style=filled, color=darkseagreen3'
WHEN event_name LIKE 'wait/synch/rwlock%' THEN
'style=filled, color=orchid'
WHEN event_name LIKE 'wait/synch/sxlock%' THEN
'style=filled, color=palevioletred'
WHEN event_name LIKE 'wait/lock%' THEN
'shape=box, style=filled, color=tan'
WHEN event_name LIKE 'statement/%' THEN
CONCAT('shape=box, style=bold',
-- Style statements depending on COM vs SQL
CASE WHEN event_name LIKE 'statement/com/%' THEN
' style=filled, color=darkseagreen'
ELSE
-- Use long query time from the server to
-- flag long running statements in red
IF((timer_wait/1000000000000) > @@long_query_time,
' style=filled, color=red',
' style=filled, color=lightblue')
END
)
WHEN event_name LIKE 'transaction' THEN
'shape=box, style=filled, color=lightblue3'
WHEN event_name LIKE 'stage/%' THEN
'style=filled, color=slategray3'
-- IDLE events are on their own, call attention to them
WHEN event_name LIKE '%idle%' THEN
'shape=box, style=filled, color=firebrick3'
ELSE '' END,
'];\n'
) event, event_id
FROM (
-- Select all transactions
(SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id,
CONCAT('trx_id: ', IFNULL(trx_id, ''), '\\n',
'gtid: ', IFNULL(gtid, ''), '\\n',
'state: ', state, '\\n',
'mode: ', access_mode, '\\n',
'isolation: ', isolation_level, '\\n',
'autocommit: ', autocommit, '\\n',
'savepoints: ', number_of_savepoints, '\\n'
) AS wait_info
FROM performance_schema.events_transactions_history_long
WHERE thread_id = in_thread_id AND event_id > v_min_event_id)
UNION
-- Select all statements, with the extra tracing information available
(SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id,
CONCAT('statement: ', sql_text, '\\n',
'errors: ', errors, '\\n',
'warnings: ', warnings, '\\n',
'lock time: ', sys.format_time(lock_time),'\\n',
'rows affected: ', rows_affected, '\\n',
'rows sent: ', rows_sent, '\\n',
'rows examined: ', rows_examined, '\\n',
'tmp tables: ', created_tmp_tables, '\\n',
'tmp disk tables: ', created_tmp_disk_tables, '\\n'
'select scan: ', select_scan, '\\n',
'select full join: ', select_full_join, '\\n',
'select full range join: ', select_full_range_join, '\\n',
'select range: ', select_range, '\\n',
'select range check: ', select_range_check, '\\n',
'sort merge passes: ', sort_merge_passes, '\\n',
'sort rows: ', sort_rows, '\\n',
'sort range: ', sort_range, '\\n',
'sort scan: ', sort_scan, '\\n',
'no index used: ', IF(no_index_used, 'TRUE', 'FALSE'), '\\n',
'no good index used: ', IF(no_good_index_used, 'TRUE', 'FALSE'), '\\n'
) AS wait_info
FROM performance_schema.events_statements_history_long
WHERE thread_id = in_thread_id AND event_id > v_min_event_id)
UNION
-- Select all stages
(SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id, null AS wait_info
FROM performance_schema.events_stages_history_long
WHERE thread_id = in_thread_id AND event_id > v_min_event_id)
UNION
-- Select all events, adding information appropriate to the event
(SELECT thread_id, event_id,
CONCAT(event_name,
IF(event_name NOT LIKE 'wait/synch/mutex%', IFNULL(CONCAT(' - ', operation), ''), ''),
IF(number_of_bytes IS NOT NULL, CONCAT(' ', number_of_bytes, ' bytes'), ''),
IF(event_name LIKE 'wait/io/file%', '\\n', ''),
IF(object_schema IS NOT NULL, CONCAT('\\nObject: ', object_schema, '.'), ''),
IF(object_name IS NOT NULL,
IF (event_name LIKE 'wait/io/socket%',
-- Print the socket if used, else the IP:port as reported
CONCAT('\\n', IF (object_name LIKE ':0%', @@socket, object_name)),
object_name),
''
),
IF(index_name IS NOT NULL, CONCAT(' Index: ', index_name), ''), '\\n'
) AS event_name,
timer_wait, timer_start, nesting_event_id, source AS wait_info
FROM performance_schema.events_waits_history_long
WHERE thread_id = in_thread_id AND event_id > v_min_event_id)
) events
ORDER BY event_id;
DECLARE CONTINUE HANDLER FOR NOT FOUND SET v_done = TRUE;
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());
IF (in_auto_setup) THEN
CALL sys.ps_setup_save(0);
-- Ensure only the thread to create the stack trace for is instrumented and that we instrument everything.
DELETE FROM performance_schema.setup_actors;
UPDATE performance_schema.threads
SET INSTRUMENTED = IF(THREAD_ID = in_thread_id, 'YES', 'NO');
-- only the %_history_long tables and it ancestors are needed
UPDATE performance_schema.setup_consumers
SET ENABLED = 'YES'
WHERE NAME NOT LIKE '%\_history';
UPDATE performance_schema.setup_instruments
SET ENABLED = 'YES',
TIMED = 'YES';
END IF;
IF (in_start_fresh) THEN
TRUNCATE performance_schema.events_transactions_history_long;
TRUNCATE performance_schema.events_statements_history_long;
TRUNCATE performance_schema.events_stages_history_long;
TRUNCATE performance_schema.events_waits_history_long;
END IF;
DROP TEMPORARY TABLE IF EXISTS tmp_events;
CREATE TEMPORARY TABLE tmp_events (
event_id bigint unsigned NOT NULL,
event longblob,
PRIMARY KEY (event_id)
);
-- Print headers for a .dot file
INSERT INTO tmp_events VALUES (0, CONCAT('digraph events { rankdir=LR; nodesep=0.10;\n',
'// Stack created .....: ', NOW(), '\n',
'// MySQL version .....: ', VERSION(), '\n',
'// MySQL hostname ....: ', @@hostname, '\n',
'// MySQL port ........: ', @@port, '\n',
'// MySQL socket ......: ', @@socket, '\n',
'// MySQL user ........: ', CURRENT_USER(), '\n'));
SELECT CONCAT('Data collection starting for THREAD_ID = ', in_thread_id) AS 'Info';
SET v_min_event_id = 0,
v_start = UNIX_TIMESTAMP(),
in_interval = IFNULL(in_interval, 1.00),
in_max_runtime = IFNULL(in_max_runtime, 60.00);
WHILE (v_runtime < in_max_runtime
AND (SELECT INSTRUMENTED FROM performance_schema.threads WHERE THREAD_ID = in_thread_id) = 'YES') DO
SET v_done = FALSE;
OPEN c_stack;
c_stack_loop: LOOP
FETCH c_stack INTO v_event, v_min_event_id;
IF v_done THEN
LEAVE c_stack_loop;
END IF;
IF (LENGTH(v_event) > 0) THEN
INSERT INTO tmp_events VALUES (v_min_event_id, v_event);
END IF;
END LOOP;
CLOSE c_stack;
SELECT SLEEP(in_interval) INTO @sleep;
SET v_runtime = (UNIX_TIMESTAMP() - v_start);
END WHILE;
INSERT INTO tmp_events VALUES (v_min_event_id+1, '}');
SET @query = CONCAT('SELECT event FROM tmp_events ORDER BY event_id INTO OUTFILE ''', in_outfile, ''' FIELDS ESCAPED BY '''' LINES TERMINATED BY ''''');
PREPARE stmt_output FROM @query;
EXECUTE stmt_output;
DEALLOCATE PREPARE stmt_output;
SELECT CONCAT('Stack trace written to ', in_outfile) AS 'Info';
SELECT CONCAT('dot -Tpdf -o /tmp/stack_', in_thread_id, '.pdf ', in_outfile) AS 'Convert to PDF';
SELECT CONCAT('dot -Tpng -o /tmp/stack_', in_thread_id, '.png ', in_outfile) AS 'Convert to PNG';
DROP TEMPORARY TABLE tmp_events;
-- Reset the settings for the performance schema
IF (in_auto_setup) 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 ;
- 示例
# 会话1查询connection_id()对应的thread_id
root@localhost : luoxiaobo 10:49:06> select thread_id from performance_schema.threads where processlist_id=connection_id();
+-----------+
| thread_id |
+-----------+
| 48 |
+-----------+
1 row in set (0.00 sec)
# 会话2使用这个ID值调用存储过程ps_trace_thread()
root@localhost : sys 10:50:14> CALL sys.ps_trace_thread(48, CONCAT('/tmp/stack-', REPLACE(NOW(), ' ', '-'), '.dot'), NULL, NULL, TRUE, TRUE, TRUE);
+-------------------+
| summary |
+-------------------+
| Disabled 1 thread |
+-------------------+
1 row in set (0.02 sec)
+---------------------------------------------+
| Info |
+---------------------------------------------+
| Data collection starting for THREAD_ID = 48 |
+---------------------------------------------+
1 row in set (0.03 sec)
# 回到会话1中执行一些DML语句
root@localhost : luoxiaobo 11:01:01> select * from t_luoxiaobo limit 100000,10;
+--------+------+---------------------+-------+
| id | test | datet_time | test1 |
+--------+------+---------------------+-------+
| 331043 | 1 | 2017-07-04 00:13:34 | NULL |
| 331045 | 2 | 2017-07-04 00:13:34 | NULL |
| 331047 | 1 | 2017-07-04 00:13:34 | NULL |
| 331049 | 2 | 2017-07-04 00:13:34 | NULL |
| 331051 | 1 | 2017-07-04 00:13:34 | NULL |
| 331053 | 2 | 2017-07-04 00:13:34 | NULL |
| 331055 | 1 | 2017-07-04 00:13:34 | NULL |
| 331057 | 2 | 2017-07-04 00:13:34 | NULL |
| 331059 | 1 | 2017-07-04 00:13:34 | NULL |
| 331061 | 2 | 2017-07-04 00:13:34 | NULL |
+--------+------+---------------------+-------+
10 rows in set (0.03 sec)
......
# 回到会话2中，等待结果返回
......
+-----------------------------------------------------------+
| Info |
+-----------------------------------------------------------+
| Stack trace written to /tmp/stack-2017-09-08-23:23:43.dot |
+-----------------------------------------------------------+
1 row in set (1 min 0.15 sec)
+-------------------------------------------------------------------+
| Convert to PDF |
+-------------------------------------------------------------------+
| dot -Tpdf -o /tmp/stack_48.pdf /tmp/stack-2017-09-08-23:23:43.dot |
+-------------------------------------------------------------------+
1 row in set (1 min 0.15 sec)
+-------------------------------------------------------------------+
| Convert to PNG |
+-------------------------------------------------------------------+
| dot -Tpng -o /tmp/stack_48.png /tmp/stack-2017-09-08-23:23:43.dot |
+-------------------------------------------------------------------+
1 row in set (1 min 0.15 sec)
+------------------+
| summary |
+------------------+
| Enabled 1 thread |
+------------------+
1 row in set (1 min 0.38 sec)
Query OK, 0 rows affected (1 min 0.38 sec)
- 拷贝下如上所示的两句命令进行格式转换
[root@localhost ~]# dot -Tpdf -o /tmp/stack_48.pdf /tmp/stack-2017-09-08-23:23:43.dot
[root@localhost ~]# ls -lh /tmp/stack_48.pdf
-rw-r--r-- 1 root root 118K 9月 8 23:29 /tmp/stack_48.pdf
[root@localhost ~]# dot -Tpng -o /tmp/stack_48.png /tmp/stack-2017-09-08-23:23:43.dot
[root@localhost ~]# ls -lh /tmp/stack_48.png
-rw-r--r-- 1 root root 5.8M 9月 8 23:29 /tmp/stack_48.png
-
打开这两个文件瞧瞧（还挺漂亮的说）
-
PS：注意：
- 语句时间超过10秒的生成PDF和PNG的时间可能会超级长（根据服务器硬件配置而定，dot命令可能效率也不是很高，特别是PNG格式可能会无法处理）
- 如果只是想从历史记录表中查询数据来生成开销树，可以把第五、六个传参设置为FALSE（前提是wait、stage、statuments、transaction几个事件类型的history_long表已经启用，否则dot结果文件无数据），如：CALL sys.ps_trace_thread(48, CONCAT('/tmp/stack-', REPLACE(NOW(), ' ', '-'), '.dot'), NULL, NULL, FALSE,FALSE, TRUE);
-
参考链接：https://dev.mysql.com/doc/refman/5.7/en/sys-ps-trace-thread.html
上一篇： ps_trace_statement_digest()存储过程 | 下一篇： ps_truncate_all_tables()存储过程