How to Profile MySQL Single Query

By:    Updated: February 27,2017

After we've identified a single query to optimize, we can drill into it and determine why it takes as much time as it does, and how to optimize it.

Using show profile

The show profile command is disabled by default, but can be enabled for the duration of a session (connection) simply by setting a server variable:

mysql> set profiling = 1;

After this, whenever we issue a statement to the server, it will measure the elapsed time and a few other types of data whenever the query changes from one execution state to another.

mysql> 
mysql> select * from fs_article_category limit 5 \G;
mysql> 
mysql> show profiles;
+----------+------------+-------------------------------------------+
| Query_ID | Duration   | Query                                     |
+----------+------------+-------------------------------------------+
|        1 | 0.00023275 | select * from fs_article_category limit 5 |
+----------+------------+-------------------------------------------+
mysql> 
mysql> show profile for query 1;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000054 |
| Waiting for query cache lock   | 0.000004 |
| starting                       | 0.000004 |
| checking query cache for query | 0.000078 |
| checking permissions           | 0.000011 |
| Opening tables                 | 0.000036 |
| init                           | 0.000034 |
| System lock                    | 0.000013 |
| Waiting for query cache lock   | 0.000003 |
| System lock                    | 0.000039 |
| optimizing                     | 0.000006 |
| statistics                     | 0.000021 |
| preparing                      | 0.000016 |
| executing                      | 0.000004 |
| Sending data                   | 0.000084 |
| end                            | 0.000008 |
| query end                      | 0.000033 |
| closing tables                 | 0.000012 |
| freeing items                  | 0.000011 |
| Waiting for query cache lock   | 0.000004 |
| freeing items                  | 0.000015 |
| Waiting for query cache lock   | 0.000003 |
| freeing items                  | 0.000003 |
| storing result in query cache  | 0.000004 |
| cleaning up                    | 0.000024 |
+--------------------------------+----------+
mysql> 

The profile allows us to follow through every step of the query's execution and see how long it took. We find that it's a bit hard to scan this output and see where most of the time was spent.

mysql> 
mysql> set @Query_ID = 1;
mysql> 
mysql> select STATE, sum(DURATION) as Total_Duration, \
     round(100 * sum(DURATION) /(select sum(DURATION) from information_schema.PROFILING where QUERY_ID = @Query_ID), 2) as Percentage_Duration, \
     count(*) as Calls, sum(DURATION) / count(*) as "Duration/Call" \
     from information_schema.PROFILING where QUERY_ID = @Query_ID group by STATE order by Total_Duration desc;
+--------------------------------+----------------+---------------------+-------+---------------+
| STATE                          | Total_Duration | Percentage_Duration | Calls | Duration/Call |
+--------------------------------+----------------+---------------------+-------+---------------+
| Sending data                   |       0.000084 |               16.03 |     1 |  0.0000840000 |
| checking query cache for query |       0.000078 |               14.89 |     1 |  0.0000780000 |
| starting                       |       0.000058 |               11.07 |     2 |  0.0000290000 |
| System lock                    |       0.000052 |                9.92 |     2 |  0.0000260000 |
| Opening tables                 |       0.000036 |                6.87 |     1 |  0.0000360000 |
| init                           |       0.000034 |                6.49 |     1 |  0.0000340000 |
| query end                      |       0.000033 |                6.30 |     1 |  0.0000330000 |
| freeing items                  |       0.000029 |                5.53 |     3 |  0.0000096667 |
| cleaning up                    |       0.000024 |                4.58 |     1 |  0.0000240000 |
| statistics                     |       0.000021 |                4.01 |     1 |  0.0000210000 |
| preparing                      |       0.000016 |                3.05 |     1 |  0.0000160000 |
| Waiting for query cache lock   |       0.000014 |                2.67 |     4 |  0.0000035000 |
| closing tables                 |       0.000012 |                2.29 |     1 |  0.0000120000 |
| checking permissions           |       0.000011 |                2.10 |     1 |  0.0000110000 |
| end                            |       0.000008 |                1.53 |     1 |  0.0000080000 |
| optimizing                     |       0.000006 |                1.15 |     1 |  0.0000060000 |
| storing result in query cache  |       0.000004 |                0.76 |     1 |  0.0000040000 |
| executing                      |       0.000004 |                0.76 |     1 |  0.0000040000 |
+--------------------------------+----------------+---------------------+-------+---------------+

This one is much better!

Using show status

MySQL's SHOW STATUS command returns a variety of counters. These counters tell you how often various activities took place, such as reads from an index, but they tell you nothing about how much time was consumed. The most important counters are the handler counters and the temporary file and table counters.

mysql> flush status;
mysql> select title from fs_article limit 5 \G;
mysql> show status where Variable_name like 'Handler%' or Variable_name like 'Created%';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Created_tmp_disk_tables    | 0     |
| Created_tmp_files          | 0     |
| Created_tmp_tables         | 0     |
| Handler_commit             | 1     |
| Handler_delete             | 0     |
| Handler_discover           | 0     |
| Handler_external_lock      | 2     |
| Handler_mrr_init           | 0     |
| Handler_prepare            | 0     |
| Handler_read_first         | 1     |
| Handler_read_key           | 1     |
| Handler_read_last          | 0     |
| Handler_read_next          | 0     |
| Handler_read_prev          | 0     |
| Handler_read_rnd           | 0     |
| Handler_read_rnd_next      | 5     |
| Handler_rollback           | 0     |
| Handler_savepoint          | 0     |
| Handler_savepoint_rollback | 0     |
| Handler_update             | 0     |
| Handler_write              | 0     |
+----------------------------+-------+

Using the slow query log

The slow query log entry contains just about everything we can see in "show profile" and "show status", and then some. This makes the log a very useful place to look for more detail when we find a "bad" query with pt-query-digest.

Using the Performance Schema

The MySQL Performance Schema is a feature for monitoring MySQL Server execution at a low level.

mysql> select event_name, count_star, sum_timer_wait from performance_schema.events_waits_summary_global_by_event_name order by sum_timer_wait desc limit 20;
+------------------------------------------------------+------------+------------------+
| event_name                                           | count_star | sum_timer_wait   |
+------------------------------------------------------+------------+------------------+
| idle                                                 |     159767 | 1240919798000000 |
| wait/io/table/sql/handler                            |    2467869 |    5025733483200 |
| wait/io/file/innodb/innodb_log_file                  |       2394 |    1208806476400 |
| wait/io/file/innodb/innodb_data_file                 |       8374 |     756795618800 |
| wait/lock/table/sql/handler                          |     127795 |     156141780800 |
| wait/io/file/sql/FRM                                 |       1665 |      44039191200 |
| wait/io/file/sql/ERRMSG                              |          5 |       5553422800 |
| wait/io/file/myisam/kfile                            |         33 |       3331344000 |
| wait/io/file/myisam/dfile                            |         24 |       1461775200 |
| wait/io/file/mysys/cnf                               |          5 |       1126089200 |
| wait/io/file/mysys/charset                           |          3 |        505900800 |
| wait/io/file/sql/dbopt                               |         16 |        241484800 |
| wait/io/file/sql/casetest                            |         10 |        126715200 |
| wait/io/file/sql/pid                                 |          3 |         62164800 |
| wait/io/file/sql/global_ddl_log                      |          2 |         13219200 |
| wait/io/file/archive/data                            |          1 |          7597600 |
| wait/synch/mutex/sql/MYSQL_RELAY_LOG::LOCK_commit    |          0 |                0 |
| wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_xids        |          0 |                0 |
| wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_flush_queue |          0 |                0 |
| wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_done        |          0 |                0 |
+------------------------------------------------------+------------+------------------+

 

More in Development Center
New on Valinv
Sources
  • http://dev.mysql.com/doc/refman/5.7/en/server-status-variables.html
  • http://dev.mysql.com/doc/refman/5.7/en/performance-schema.html
Related Articles
Sponsored Links