SHOW PROFILE

I’ve been playing more with the SHOW PROFILE command available as part of MySQL Community 5.0.37. Thanks to the author Jeremy Cole. This command can provide some interesting insight into the workings of MySQL. It does however like most new releases of software enable users to make suggestions for new features and functionality. Here is my wish list. Some I figure are practical, some are wish list, but if you never ask you never know.

1. The Unit of measure for duration is Second. It would be great if it could be tuned for display, say millisecond. If you look at my first Example, all figures are effectively represented in milli-second or even micro-second granularity.
2. I would like to see a total for the query. Again in Example 1, you have to add up all the figures to determine this query took 8ms.
3. Again in Example 1, perhaps a percentage of total time for each line duration may be helpful.
4. More descriptive status descriptions (this is part of the MySQL internal code and not the patch)
5. SET PROFILING=1; can only be set on a current session, making it impossible to easily monitor a JDBC multi-connection test. There needs to be a way to enable for a session, other then current interactive one you are viewing, but also be able to see results. You can’t do a SHOW PROFILE via a JDBC connection!
6. I’d like to see a threshold, so queries running under threshold are discarded, much like a long-query-time option. This enables you to run a large number of SQL Statements and only profiles for longer running ones are logged
7. I’d like to see a level of logging to file, again like a slow query log, so you can simply gather information on a working system and review at some later time. Combined with the previous point, you now have microsecond slow query log with explicit details.

One major benefit of the SHOW PROFILE command is I can accurately get a figure for how long a query it taking (time in milliseconds). You just have to sum all figures (See wish list point 2).

By default, the source details are not provided, you need to specify the SOURCE operand, which helps in both comparing with any debugging output and also trouncing through the code. As in Example 1, I needed to find why 95% of time was in a step with the most descriptive line of ‘end’.

Example 1

mysql> show profile SOURCE,MEMORY for query 4;
+--------------------+------------+-----------------------+---------------+-------------+
| Status             | Duration   | Source_function       | Source_file   | Source_line |
+--------------------+------------+-----------------------+---------------+-------------+
| Opening tables     | 0.00013200 | open_tables           | sql_base.cc   |        2106 |
| System lock        | 0.00001800 | mysql_lock_tables     | lock.cc       |         153 |
| Table lock         | 0.00000600 | mysql_lock_tables     | lock.cc       |         162 |
| init               | 0.00001300 | mysql_select          | sql_select.cc |        2073 |
| optimizing         | 0.00004800 | optimize              | sql_select.cc |         617 |
| statistics         | 0.00002500 | optimize              | sql_select.cc |         773 |
| preparing          | 0.00005200 | optimize              | sql_select.cc |         783 |
| executing          | 0.00002200 | exec                  | sql_select.cc |        1407 |
| Sending data       | 0.00000500 | exec                  | sql_select.cc |        1925 |
| end                | 0.00786600 | mysql_select          | sql_select.cc |        2118 |
| query end          | 0.00001400 | mysql_execute_command | sql_parse.cc  |        5085 |
| freeing items      | 0.00000700 | mysql_parse           | sql_parse.cc  |        5973 |
| closing tables     | 0.00001900 | dispatch_command      | sql_parse.cc  |        2120 |
| logging slow query | 0.00001000 | log_slow_statement    | sql_parse.cc  |        2178 |
| cleaning up        | 0.00000500 | dispatch_command      | sql_parse.cc  |        2143 |
+--------------------+------------+-----------------------+---------------+-------------+
15 rows in set (0.01 sec)

Example 2

We were experiencing increased latency in JDBC with a particular query, With a recommendation from MySQL Support we tried SET SQL_BUFFER_RESULT=1;

mysql> show profile source for query 14;
+------------------------------+------------+-------------------------+---------------+-------------+
| Status                       | Duration   | Source_function         | Source_file   | Source_line |
+------------------------------+------------+-------------------------+---------------+-------------+
| Opening tables               | 0.00006025 | open_tables             | sql_base.cc   |        2106 |
| System lock                  | 0.00004875 | mysql_lock_tables       | lock.cc       |         153 |
| Table lock                   | 0.00000400 | mysql_lock_tables       | lock.cc       |         162 |
| init                         | 0.00001600 | mysql_select            | sql_select.cc |        2073 |
| optimizing                   | 0.00005675 | optimize                | sql_select.cc |         617 |
| statistics                   | 0.00001250 | optimize                | sql_select.cc |         773 |
| preparing                    | 0.00005175 | optimize                | sql_select.cc |         783 |
| Creating tmp table           | 0.00001275 | optimize                | sql_select.cc |        1206 |
| executing                    | 0.00006025 | exec                    | sql_select.cc |        1407 |
| Copying to tmp table         | 0.00000400 | exec                    | sql_select.cc |        1547 |
| converting HEAP to MyISAM    | 0.04820900 | create_myisam_from_heap | sql_select.cc |        9914 |
| Copying to tmp table on disk | 0.04049075 | create_myisam_from_heap | sql_select.cc |        9968 |
| Sending data                 | 1.29302000 | exec                    | sql_select.cc |        1925 |
| end                          | 0.09398425 | mysql_select            | sql_select.cc |        2118 |
| removing tmp table           | 0.00004975 | free_tmp_table          | sql_select.cc |        9856 |
| end                          | 0.00089125 | free_tmp_table          | sql_select.cc |        9884 |
| query end                    | 0.00001850 | mysql_execute_command   | sql_parse.cc  |        5085 |
| freeing items                | 0.00000825 | mysql_parse             | sql_parse.cc  |        5973 |
| closing tables               | 0.00003425 | dispatch_command        | sql_parse.cc  |        2120 |
| logging slow query           | 0.00001325 | log_slow_statement      | sql_parse.cc  |        2178 |
| cleaning up                  | 0.00000675 | dispatch_command        | sql_parse.cc  |        2143 |
+------------------------------+------------+-------------------------+---------------+-------------+
21 rows in set (0.00 sec)

Looking at the lines helped to indicate that the temporary table was being flushed to disk, indicating we need to Add SET SESSION tmp_table_size=20*1024*1024;

mysql> show profile source for query 18;
+----------------------+------------+-----------------------+---------------+-------------+
| Status               | Duration   | Source_function       | Source_file   | Source_line |
+----------------------+------------+-----------------------+---------------+-------------+
| Opening tables       | 0.00006050 | open_tables           | sql_base.cc   |        2106 |
| System lock          | 0.00001250 | mysql_lock_tables     | lock.cc       |         153 |
| Table lock           | 0.00000400 | mysql_lock_tables     | lock.cc       |         162 |
| init                 | 0.00000775 | mysql_select          | sql_select.cc |        2073 |
| optimizing           | 0.00005475 | optimize              | sql_select.cc |         617 |
| statistics           | 0.00001225 | optimize              | sql_select.cc |         773 |
| preparing            | 0.00005075 | optimize              | sql_select.cc |         783 |
| Creating tmp table   | 0.00001350 | optimize              | sql_select.cc |        1206 |
| executing            | 0.00006125 | exec                  | sql_select.cc |        1407 |
| Copying to tmp table | 0.00000375 | exec                  | sql_select.cc |        1547 |
| Sending data         | 0.29110925 | exec                  | sql_select.cc |        1925 |
| end                  | 0.08023800 | mysql_select          | sql_select.cc |        2118 |
| removing tmp table   | 0.00001525 | free_tmp_table        | sql_select.cc |        9856 |
| end                  | 0.05971400 | free_tmp_table        | sql_select.cc |        9884 |
| query end            | 0.00001925 | mysql_execute_command | sql_parse.cc  |        5085 |
| freeing items        | 0.00000425 | mysql_parse           | sql_parse.cc  |        5973 |
| closing tables       | 0.00004625 | dispatch_command      | sql_parse.cc  |        2120 |
| logging slow query   | 0.00000800 | log_slow_statement    | sql_parse.cc  |        2178 |
| cleaning up          | 0.00000300 | dispatch_command      | sql_parse.cc  |        2143 |
+----------------------+------------+-----------------------+---------------+-------------+
19 rows in set (0.00 sec)