Channels ▼
RSS

Tools

Detailed Profiling of SQL Activity in MySQL 5.6


Finding High-Overhead Statements

With a development instance set up to trace everything, you can run tests against your applications to acquire performance metrics and focus tuning efforts. Generally, this starts with trying to pinpoint the statements with the most overhead.

In the past, this task was done by turning on the Slow Query Log, then post-processing this log file with a tool such as mysqldumpslow to aggregate the statistics. As part of the new statement instrumentation within MySQL 5.6, a handy aggregate table has been implemented: performance_schema.events_statements_summary_by_digest. With the aggregate table, you don't have to access the file system to look at the log and you can analyze the statistics easily with simple SQL.

This table has the following structure:

mysql> DESC events_statements_summary_by_digest; 
+-----------------------------+---------------------+------+-----+---------------------+-------+ 
| Field                       | Type                | Null | Key | Default             | Extra | 
+-----------------------------+---------------------+------+-----+---------------------+-------+ 
| SCHEMA_NAME                 | varchar(64)         | YES  |     | NULL                |       | 
| DIGEST                      | varchar(32)         | YES  |     | NULL                |       | 
| DIGEST_TEXT                 | longtext            | YES  |     | NULL                |       | 
| COUNT_STAR                  | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_TIMER_WAIT              | bigint(20) unsigned | NO   |     | NULL                |       | 
| MIN_TIMER_WAIT              | bigint(20) unsigned | NO   |     | NULL                |       | 
| AVG_TIMER_WAIT              | bigint(20) unsigned | NO   |     | NULL                |       | 
| MAX_TIMER_WAIT              | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_LOCK_TIME               | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_ERRORS                  | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_WARNINGS                | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_ROWS_AFFECTED           | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_ROWS_SENT               | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_ROWS_EXAMINED           | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_CREATED_TMP_DISK_TABLES | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_CREATED_TMP_TABLES      | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_SELECT_FULL_JOIN        | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_SELECT_FULL_RANGE_JOIN  | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_SELECT_RANGE            | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_SELECT_RANGE_CHECK      | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_SELECT_SCAN             | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_SORT_MERGE_PASSES       | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_SORT_RANGE              | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_SORT_ROWS               | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_SORT_SCAN               | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_NO_INDEX_USED           | bigint(20) unsigned | NO   |     | NULL                |       | 
| SUM_NO_GOOD_INDEX_USED      | bigint(20) unsigned | NO   |     | NULL                |       | 
| FIRST_SEEN                  | timestamp           | NO   |     | 0000-00-00 00:00:00 |       | 
| LAST_SEEN                   | timestamp           | NO   |     | 0000-00-00 00:00:00 |       | 
+-----------------------------+---------------------+------+-----+---------------------+-------+ 

Within this table, Performance Schema tracks and aggregates statistics by normalizing the statements, and assigning that normalized statement a "Digest," which is an MD5 hash of the normalized form of the statement. These digests are available in the DIGEST and DIGEST_TEXT columns. The table is aggregated by both the SCHEMA_NAME and DIGEST columns, so that you can also drill into which schemas are generating the most overhead, even if you have an instance that has multiple schemas executing the same kinds of statements (such as a shared instance running multiple Wordpress installations, for example).

A normalized statement may have any of the following actions performed upon it:

  • Stripping whitespace
  • Stripping comments
    • Replacing literals (integer and string inputs) with a "?" placeholder. For example, SELECT foo, bar FROM foobar WHERE foo = 100 becomes SELECT foo, bar FROM foobar WHERE foo = ?
  • Lists of values are folded
    • Folding lists of IN values. For example, SELECT foo FROM foobar WHERE bar IN (1, 2, 3) becomes SELECT foo FROM foobar WHERE bar IN (...)
    • Folding multirow INSERTs. For example, INSERT INTO t1 VALUES (1, 2, 3), (4, 5, 6) becomes INSERT INTO t1 VALUES (...) /* , ... */
    • Listing of values in the SELECT list. For example, SELECT 1, 2, 3, foo, bar FROM foobar becomes SELECT ?, ... , foo, bar FROM foobar
    • Long normalized statements are truncated, with "..." added at the end. "Long" is currently defined as 1024 bytes; however, note that this is on the normalized statement, so large string values are not a concern

Finding the statements that have the highest latency in the server is simple: just specify a criteria against one of the *_TIMER_WAIT columns. For instance, to find the top five statements that have the highest latency overall (and are probably prime candidates for tuning):

SELECT * 
FROM performance_schema.events_statements_summary_by_digest
ORDER BY SUM_TIMER_WAIT DESC LIMIT 5\G

******************** 1. row ***********************
SCHEMA_NAME: mysql
     DIGEST: a3efbb2ddf943115f3cb50b810910160
     DIGEST_TEXT: SELECT * FROM ( SELECT username AS `user` ... 
COUNT_STAR: 27757
SUM_TIMER_WAIT: 3753097139331384
MIN_TIMER_WAIT: 30471498720
AVG_TIMER_WAIT: 135212475084
MAX_TIMER_WAIT: 18453317809272
SUM_LOCK_TIME: 33214892000000
SUM_ERRORS: 0
SUM_WARNINGS: 0
SUM_ROWS_AFFECTED: 0
SUM_ROWS_SENT: 5987687
SUM_ROWS_EXAMINED: 263772439
SUM_CREATED_TMP_DISK_TABLES: 83271
SUM_CREATED_TMP_TABLES: 194299
SUM_SELECT_FULL_JOIN: 83271
SUM_SELECT_FULL_RANGE_JOIN: 0
SUM_SELECT_RANGE: 0
SUM_SELECT_RANGE_CHECK: 0
SUM_SELECT_SCAN: 166542
SUM_SORT_MERGE_PASSES: 0
SUM_SORT_RANGE: 0
SUM_SORT_ROWS: 685834
SUM_SORT_SCAN: 25134
SUM_NO_INDEX_USED: 27757
SUM_NO_GOOD_INDEX_USED: 0
         FIRST_SEEN: 2012-12-06 21:19:50
         LAST_SEEN: 2012-12-31 11:20:28

(The DIGEST_TEXT column has been truncated for brevity.)

There are several things of interest in this raw data:

  • The statement is scanning many more rows than are actually sent back to the client (SUM_ROWS_SENT is much less than SUM_ROWS_EXAMINED, on average the statement is scanning some 9,500 rows to return around 215 rows per execution). This is likely due to the fact that no index is ever being used to satisfy the query (SUM_NO_INDEX_USED == COUNT_STAR).
  • The statement is creating a lot of temporary tables (an average of seven per execution), and more than 40% of those are on disk averaging three per execution (SUM_CREATED_TMP_TABLES vs. SUM_CREATED_TMP_DISK_TABLES)
  • Interestingly, we seem to be doing joining against the temporary tables that are created on disk, and that's not using an index (SUM_SELECT_FULL_JOIN == SUM_CREATED_TMP_DISK_TABLES)

This statement is certainly worth tuning. First, try and find the right combination of indexes within your schema to satisfy the query, and also to see if something can be done about the excessive temporary table use — first by seeing if it can be created in memory only (assuming it has no long text columns and so forth). If not, try to make it perform better, perhaps by creating the temporary table up front with an index defined.

There are items that can be identified with this table as well:

  • Finding statements that cause errors or warnings: SUM_ERRORS > 0 OR SUM_WARNINGS > 0
  • Finding statements that always create temporary tables on disk: SUM_CREATED_TMP_TABLES = SUM_CREATED_TMP_DISK_TABLES
  • Finding new statements that have turned up in your applications: FIRST_SEEN > (NOW() - INTERVAL 2 DAY)

Locating Where Statements Have High Latency

Once you have identified a statement to tune, you can infer where problems might lie; however, a more scientific approach would be to find out exactly where the time is being spent within the statement's execution window. This is what the new Stages instrumentation is for. Stages record the time that a connection spends in the various thread states that you see within the output of something like SHOW PROCESSLIST.

In the past, you might have used SHOW PROFILE to get this kind of data. If so, this approach should be fairly familiar to you. The new Stages instrumentation within Performance Schema in MySQL 5.6 is intended to eventually replace SHOW PROFILE (which has been deprecated), and it has several advantages:

  • You can now get stage/state information for all connections, not just your current connection
  • Stages are linked to statements, and linked further to underlying waits (more on this shortly)
  • Stages are exposed in regular tables, giving you a SQL interface to look at the data
  • Stage instruments are aggregated in multiple ways: globally, by thread, by user, by host, by account (user@host)

When profiling a specific statement, you are not interested in the aggregated information. Rather, you need to drill down into the raw data that is linked to a specific statement. On a busy system, this data can be particularly volatile, however, so you need to take this into account and set up your environment appropriately.


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