The dump_thread_stack() procedure selects all data within MySQL’s performance_schema database (on MySQL 5.6.3 and above), for an instrumented thread, to output to a DOT formatted graph file. This file can then be loaded in to a graphing package, such as Graphviz or pydot, to generate a graph of all of the statements, and wait events within those statements, for the thread.
This requires the events_statements_history_long, events_stages_history_long and events_waits_history_long table consumers to be enabled, as this kind of wait information can be extremely verbose depending on the level of instrumentation that you have enabled.
For a true graph to be created, you will also need to ensure that each level of instrumentation is enabled – at a bare minimum you should have all statement/% and stage/% instrumentation enabled within the setup_instruments table as well, as wait events link to stages, which in turn link to statements.
MySQL Versions: 5.6.3+
Examples
First you need to find the thread id for the connection that you are interested in dumping the thread stack for. To do this you can look directly within the performance_schema.threads table:
mysql> SELECT thread_id, processlist_id, processlist_user, processlist_host
-> FROM performance_schema.threads
-> WHERE type = 'foreground';
+-----------+----------------+------------------+------------------+
| thread_id | processlist_id | processlist_user | processlist_host |
+-----------+----------------+------------------+------------------+
| 23 | 2 | root | localhost |
+-----------+----------------+------------------+------------------+
You then use this thread_id when calling the stored procedure. You can dump the output to a file from the command line with:
$ mysql -u root -BN -e "CALL ps_helper.dump_thread_stack(23,true)" > /tmp/stack.dot
Then load /tmp/stack.dot in to your graphing package of choice and enjoy!
Each node of the graph is coloured according to the type of event:
Idle time:fireBrick3
COM Commands: darkSeaGreen
Statements: lightBlue when under long_query_time, and red when above it
Stages: slateGray3
Network IO:yellow
Table IO:green
File IO:red
Table Locks:tan
Mutexes:lightSkyBlue
RW Locks:orchid
Conditions:darkSeaGreen3
Parameters
thd_id: The thread that you would like a stack trace for
debug: Whether you would like to include file:lineno in the graph (true|false)
Source
DROP PROCEDURE IF EXISTS dump_thread_stack;
DELIMITER $$
CREATE PROCEDURE dump_thread_stack(thd_id INT, debug BOOLEAN)
BEGIN
/* Do not track the current thread, it will kill the stack */
CALL disable_current_thread();
/* Print headers for a .dot file */
SELECT 'digraph events { rankdir=LR; nodesep=0.10;';
SELECT CONCAT('// Stack created: ', NOW());
SELECT CONCAT('// MySQL version: ', VERSION());
SELECT CONCAT('// MySQL user: ', CURRENT_USER());
/* Select the entire stack of events */
SELECT CONCAT(IF(nesting_event_id IS NOT NULL, CONCAT(nesting_event_id, ' -> '), ''),
event_id, '; ', event_id, ' [label="',
/* Convert from picoseconds to microseconds */
'(',ROUND(timer_wait/1000000, 2),'μ) ',
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 statements */
IF (event_name LIKE 'statement/%', IFNULL(CONCAT('\n', wait_info), ''), ''),
/* If debug is enabled, add the file:lineno information for waits */
IF (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/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 '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,
'];') event
FROM (
/* Select all statements, with the extra tracing information available */
(SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id,
CONCAT(sql_text, '\n',
'errors: ', errors, '\n',
'warnings: ', warnings, '\n',
'lock time: ', ROUND(lock_time/1000000, 2),'μ\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)
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)
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)) events
WHERE thread_id = thd_id
ORDER BY event_id;
SELECT '}';
END$$
DELIMITER ;
One comment