-- Copyright (c) 2014, 2015, Oracle and/or its affiliates. All rights reserved. -- -- This program is free software; you can redistribute it and/or modify -- it under the terms of the GNU General Public License as published by -- the Free Software Foundation; version 2 of the License. -- -- This program is distributed in the hope that it will be useful, -- but WITHOUT ANY WARRANTY; without even the implied warranty of -- MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the -- GNU General Public License for more details. -- -- You should have received a copy of the GNU General Public License -- along with this program; if not, write to the Free Software -- Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA DROP PROCEDURE IF EXISTS ps_trace_thread; DELIMITER $$ CREATE DEFINER='mariadb.sys'@'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 statements 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/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) > @@log_slow_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, '];\n' ) event, event_id 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: ', 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_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 ;