One of my favorite tools for query optimization is profiling. But recently I noticed this warning:

mysql> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> show warnings; +———+——+———————————————————————-+ | Level | Code | Message | +———+——+———————————————————————-+ | Warning | 1287 | ‘@@profiling’ is deprecated and will be removed in a future release. | +———+——+———————————————————————-+

After looking through the MySQL documentation, I should indeed start using the Performance Schema to get this information.

Okay, so let’s give that a try.

I confirmed that I started MySQL 5.6.23 with the default of Performance Schema = ON:

mysql> show global variables like ‘%perf%’;
+——————————————————–+——-+
| Variable_name                                          | Value |
+——————————————————–+——-+
| performance_schema                                     | ON    |

I’ll be using a development server for doing query profiling, so I can turn all of these on:

mysql> update performance_schema.setup_instruments set enabled=‘YES’, timed=‘YES’; #you want the stage* ones enabled
mysql> update performance_schema.setup_consumers set enabled=‘YES’; #you want the events_statements_history* and events_stages_history* enabled

Start with fresh collection tables:

mysql> truncate performance_schema.events_stages_history_long;
mysql> truncate performance_schema.events_statements_history_long;

Then turn the profiler on:

mysql> set profiling=1;

Now run a sample query:

mysql> select distinct(msa) from zip.codes;

And find the resulting event IDs to use in the query below:

mysql> select event_id, end_event_id, sql_text from performance_schema.events_statements_history_long where sql_text like ‘%msa%’;
…
|      41 |       938507 | select distinct(msa) from zip.codes                                                                  |

Insert those beginning and ending event IDs, and here’s the new profiling output on my test query from Performance Schema:

mysql> select substring_index(event_name,‘/’,-1) as Status, truncate((timer_end-timer_start)/1000000000000,6) as Duration from performance_schema.events_stages_history_long where event_id>=41 and event_id<=938507;

+———————-+———-+ | Status | Duration | +———————-+———-+ | init | 0.000103 | | checking permissions | 0.000006 | | Opening tables | 0.000051 | | init | 0.000014 | | System lock | 0.000007 | | optimizing | 0.000003 | | statistics | 0.000011 | | preparing | 0.000011 | | Creating tmp table | 0.000048 | | executing | 0.000002 | | Sending data | 1.251331 | | end | 0.000003 | | removing tmp table | 0.000008 | | query end | 0.000006 | | closing tables | 0.000009 | | freeing items | 0.000111 | | cleaning up | 0.000002 | +———————-+———-+

Compare the legacy profiling available for the query:

mysql> show profile for query 1;
+———————-+———-+
| Status               | Duration |
+———————-+———-+
| starting             | 0.000125 |
| checking permissions | 0.000007 |
| Opening tables       | 0.000020 |
| init                 | 0.000014 |
| System lock          | 0.000007 |
| optimizing           | 0.000003 |
| statistics           | 0.000011 |
| preparing            | 0.000011 |
| Creating tmp table   | 0.000027 |
| executing            | 0.000001 |
| Sending data         | 1.353825 |
| end                  | 0.000005 |
| removing tmp table   | 0.000007 |
| end                  | 0.000002 |
| query end            | 0.000006 |
| closing tables       | 0.000009 |
| freeing items        | 0.000069 |
| cleaning up          | 0.000028 |
+———————-+———-+

The obvious question is: Why I would want to be limited to this information when the Performance Schema has so much more available?

But this proves we can get profiler information in a format we’re used to when MySQL fully deprecates the profiling tool.

(Originally published at: https://www.pythian.com/blog/mysql-query-profiling-with-performance-schema/)