Channels ▼
RSS

Database

Detailed Profiling of SQL Activity in MySQL 5.6


One of the easy ways to focus your profiling efforts is to turn off instrumentation for all threads apart from the one that you are examining. This will allow you to look at the history tables and see only data that is relevant to your tuning efforts, while also helping to ensure that no other activity on the instance ages out the data that you are trying to analyze.

This is where the performance_schema.threads table can help. This table exposes the same data as the output of SHOW PROCESSLIST, and also provides information on all background threads:

SELECT * FROM performance_schema.threads\G 
	...
	*************************** 19. row *************************** 
      		  THREAD_ID: 20 
      	   	       NAME: thread/sql/one_connection 
      	                           TYPE: FOREGROUND 
	     PROCESSLIST_ID: 1 
	   PROCESSLIST_USER: root 
	   PROCESSLIST_HOST: localhost 
	     PROCESSLIST_DB: performance_schema 
	PROCESSLIST_COMMAND: Query 
	   PROCESSLIST_TIME: 0 
	  PROCESSLIST_STATE: Sending data 
	   PROCESSLIST_INFO: SELECT * FROM performance_schema.threads 
	   PARENT_THREAD_ID: 1 
	               ROLE: NULL 
	       INSTRUMENTED: YES 

However, the table also has an INSTRUMENTED column that, like the setup_* tables, can be updated at runtime to turn on and off instrumentation by thread. To disable all threads before running your tests:

UPDATE performance_schema.threads SET instrumented = 'NO'; 

New connections will still be instrumented (unless you also update the setup_actors table appropriately, by removing the default row). So, make sure you're not running any other application tests against your development instance, then make a new connection to run the specific statement(s) that you want to tune.

Stages do not have a DIGEST column from which to infer a statement, but they are linked to statements using event nesting. Each of the history tables has an EVENT_ID column for the current event, and a NESTING_EVENT_ID column, which is the event ID of its parent event.

With these you can JOIN the events_statements_history_long table to the events_stages_history_long. If you have just executed one statement to profile, you can do this easily with a derived table:

SELECT event_name, timer_wait/1000000000 wait_ms 
	  FROM events_stages_history_long AS stages 
       	    JOIN (SELECT event_id 
                	         FROM events_statements_history_long 
               	         ORDER BY event_id DESC limit 1) AS statements 
          ON stages.nesting_event_id = statements.event_id 
        	  ORDER BY stages.event_id;

	+--------------------------------+---------+
	| event_name                     | wait_ms |
	+--------------------------------+---------+
	| stage/sql/init                 |  0.0755 |
	| stage/sql/checking permissions |  0.0020 |
	| stage/sql/checking permissions |  0.0066 |
	| stage/sql/Opening tables       |  0.1513 |
	| stage/sql/init                 |  0.0119 |
	| stage/sql/System lock          |  0.0036 |
	| stage/sql/optimizing           |  0.0013 |	
	| stage/sql/optimizing           |  0.0060 |
	| stage/sql/statistics           |  0.0103 |
	| stage/sql/preparing            |  0.0079 |
	| stage/sql/Sorting result       |  0.0086 |
	| stage/sql/executing            |  0.0007 |
	| stage/sql/Sending data         |  0.0010 |
	| stage/sql/Creating sort index  |  0.5062 |
	| stage/sql/statistics           |  0.0079 |
	| stage/sql/preparing            |  0.0030 |
	| stage/sql/Sorting result       |  0.0007 |
	| stage/sql/executing            |  0.0003 |
	| stage/sql/Sending data         |  0.0040 |
	| stage/sql/Creating sort index  |  0.0987 |
	| stage/sql/end                  |  0.0013 |
	| stage/sql/query end            |  0.0013 |
	| stage/sql/closing tables       |  0.0003 |
	| stage/sql/removing tmp table   |  0.0036 |
	| stage/sql/freeing items        |  0.0374 |
	| stage/sql/cleaning up          |  0.0083 |
	+--------------------------------+---------+

Here, the longest period of waiting is during the "Creating sort index" stage, which is again related to creating a temporary table to satisfy a SELECT query. You can order this in any way you like (the example is chronologically), such as ORDER BY timer_wait DESC, for example, to make it more obvious which stages are the highest consumers of time.

If you have executed many queries, then you will want to look at these on a per-statement basis, finding each event_id from events_statements_history_long, and then selecting from the events_stages_history_long table using that id to filter on the NESTING_EVENT_ID column.

But it doesn't stop here; you can drill further into each of the wait events during each stage. This can be particularly telling if you have to do a lot of I/O, for example.

To look at the entire history of the thread, you can use a statement like the following example. It will dump the entire history available in order. This may start out with just statements, and no relating stage/wait events, depending on how many statements you have executed on the thread. It will give progressively more information as you track the thread history.

  SELECT thread_id, 
         CONCAT( CASE WHEN event_name LIKE 'stage%' THEN
                       CONCAT('  ', event_name)
                     WHEN event_name LIKE 'wait%' AND nesting_event_id IS NOT NULL THEN
                       CONCAT('    ', event_name)
                     ELSE IF(digest_text IS NOT NULL, SUBSTR(digest_text, 1, 64), event_name)
               END,
               ' (',ROUND(timer_wait/1000000, 2),'μ) ') event
   FROM (
         (SELECT thread_id, event_id, event_name, 
                 timer_wait, timer_start, nesting_event_id, digest_text
            FROM events_statements_history_long)
         UNION
         (SELECT thread_id, event_id, event_name,
                 timer_wait, timer_start, nesting_event_id, NULL
            FROM events_stages_history_long)
         UNION
         (SELECT thread_id, event_id, event_name, 
                 timer_wait, timer_start, nesting_event_id, NULL
            FROM events_waits_history_long)
        ) events
  ORDER BY thread_id, event_id;

+-----------+-----------------------------------------------------------------------------+
| thread_id | event                                                                       |
+-----------+-----------------------------------------------------------------------------+
|   2782380 | DELETE FROM `env_inventory` . `Network_v4Addresses` WHERE `Netw (71.18µ)    |
|   2782380 | DELETE FROM `env_inventory` . `Network_v6Addresses` WHERE `Netw (69.19µ)    |
|   2782380 | COMMIT  (612.14µ)                                                           |
...
|   2782380 | INSERT INTO `env_inventory` . `Network_v4Addresses` ( `Network` (77.47µ)    |
|   2782380 |   stage/sql/end (0.66µ)                                                     |
|   2782380 |   stage/sql/query end (0.99µ)                                               |
|   2782380 |   stage/sql/closing tables (1.99µ)                                          |
|   2782380 |   stage/sql/freeing items (21.85µ)                                          |
|   2782380 |   stage/sql/cleaning up (0.66µ)                                             |
|   2782380 | COMMIT  (903.82µ)                                                           |
|   2782380 |   stage/sql/init (860.78µ)                                                  |
|   2782380 |   stage/sql/query end (1.32µ)                                               |
|   2782380 |   stage/sql/closing tables (0.99µ)                                          |
|   2782380 |   stage/sql/freeing items (39.40µ)                                          |
|   2782380 |   stage/sql/cleaning up (0.66µ)                                             |
...
|   2782380 | idle (40.72µ)                                                               |
|   2782380 | INSERT INTO `env_inventory` . `Network_v4Addresses` ( `Network` (77.47µ)    |
|   2782380 |   stage/sql/init (15.89µ)                                                   |
|   2782380 |     wait/io/socket/sql/client_connection (1.41µ)                            |
|   2782380 |     wait/io/socket/sql/client_connection (1.00µ)                            |
|   2782380 |     wait/synch/mutex/sql/THD::LOCK_thd_data (0.04µ)                         |
|   2782380 |     wait/synch/mutex/sql/THD::LOCK_thd_data (0.03µ)                         |
|   2782380 |   stage/sql/checking permissions (1.32µ)                                    |
|   2782380 |     wait/synch/rwlock/sql/LOCK_grant (0.13µ)                                |
|   2782380 |   stage/sql/Opening tables (4.30µ)                                          |
|   2782380 |     wait/synch/rwlock/sql/MDL_lock::rwlock (0.06µ)                          |
|   2782380 |     wait/synch/mutex/sql/LOCK_table_cache (0.06µ)                           |
|   2782380 |     wait/synch/mutex/sql/THD::LOCK_thd_data (0.03µ)                         |
|   2782380 |   stage/sql/init (3.97µ)                                                    |
|   2782380 |   stage/sql/System lock (1.32µ)                                             |
|   2782380 |     wait/lock/table/sql/handler (0.33µ)                                     |
|   2782380 |     wait/lock/table/sql/handler (0.29µ)                                     |
|   2782380 |     wait/synch/mutex/mysys/THR_LOCK::mutex (0.06µ)                          |
|   2782380 |   stage/sql/update (23.84µ)                                                 |
|   2782380 |     wait/io/table/sql/handler (21.77µ)                                      |
|   2782380 |     wait/synch/rwlock/innodb/dict_operation_lock (0.09µ)                    |
|   2782380 |     wait/synch/rwlock/innodb/btr_search_latch (0.06µ)                       |
|   2782380 |     wait/synch/mutex/innodb/lock_mutex (0.08µ)                              |
...

As you can imagine, there are many more options that can provide useful data for tuning the performance of MySQL. Many of those options are explained in greater detail in the links throughout this article. In all cases, if your work requires improving MySQL performance, you'll find the new Performance Schema to be a boon to your efforts.


Mark Leith is a Senior Software Development Manager, MySQL Enterprise Tools Group.


Related Reading


More Insights






Currently we allow the following HTML tags in comments:

Single tags

These tags can be used alone and don't need an ending tag.

<br> Defines a single line break

<hr> Defines a horizontal line

Matching tags

These require an ending tag - e.g. <i>italic text</i>

<a> Defines an anchor

<b> Defines bold text

<big> Defines big text

<blockquote> Defines a long quotation

<caption> Defines a table caption

<cite> Defines a citation

<code> Defines computer code text

<em> Defines emphasized text

<fieldset> Defines a border around elements in a form

<h1> This is heading 1

<h2> This is heading 2

<h3> This is heading 3

<h4> This is heading 4

<h5> This is heading 5

<h6> This is heading 6

<i> Defines italic text

<p> Defines a paragraph

<pre> Defines preformatted text

<q> Defines a short quotation

<samp> Defines sample computer code text

<small> Defines small text

<span> Defines a section in a document

<s> Defines strikethrough text

<strike> Defines strikethrough text

<strong> Defines strong text

<sub> Defines subscripted text

<sup> Defines superscripted text

<u> Defines underlined text

Dr. Dobb's encourages readers to engage in spirited, healthy debate, including taking us to task. However, Dr. Dobb's moderates all comments posted to our site, and reserves the right to modify or remove any content that it determines to be derogatory, offensive, inflammatory, vulgar, irrelevant/off-topic, racist or obvious marketing or spam. Dr. Dobb's further reserves the right to disable the profile of any commenter participating in said activities.

 
Disqus Tips To upload an avatar photo, first complete your Disqus profile. | View the list of supported HTML tags you can use to style comments. | Please read our commenting policy.
 

Video