MySQL Statement Profiling Is Easier Now!

If you has always wanted to know why your SQL statement runs so slow and you are a MySQL DBA, you probably used the explain command to understand the estimated execution plan.


Yet, how could you know what part of the execution will take most time when you'll process the SQL Statement? Will it be the I/O, the sorting, data sending or freeing items?


One Step Ahead
The answer is simpler than you think: MySQL Profiler, a built in command line in MySQL from version 5.0, that let us know exactly why our statement take so long.


How to Do That?

1. Decide how many queries do you want to profile: the default number is 15 and can be changed to 1 through 100 using the profiling_history_size session variable.
2. Enable the MySQL Profiler.
3. Perform the query.
4. See the exact running time.
5. Analyze the results.
6. Disable the MySQL Profiler.

Give Us Some Code!
mysql> SET PROFILING=1;
mysql> SELECT * FROM buffer_log WHERE buffer_num=1 ORDER BY end_date DESC limit 100;
mysql> select sum(duration) from information_schema.profiling where query_id=1;
mysql> show profile for QUERY 1;

+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000022 |
| checking query cache for query | 0.000064 |
| Opening tables                 | 0.000011 |
| System lock                    | 0.000003 |
| Table lock                     | 0.000029 |
| init                           | 0.000027 |
| optimizing                     | 0.000008 |
| statistics                     | 0.020821 |
| preparing                      | 0.000023 |
| executing                      | 0.000004 |
| Sorting result                 | 0.291548 |
| Sending data                   | 0.000317 |
| end                            | 0.000004 |
| end                            | 0.000003 |
| query end                      | 0.000003 |
| storing result in query cache  | 0.000007 |
| freeing items                  | 0.000011 |
| closing tables                 | 0.000003 |
| logging slow query             | 0.000001 |
| cleaning up                    | 0.000004 |
+--------------------------------+----------+

mysql> SET PROFILING=0;

In this case you can easily see that sorting is our major issue. If you may run an explain command you could easily see that there is no index on end_date field.


More Tips by Ben and JRRL3

1. It does not require admin permissions.
2. It should be run from command line (and not from external tools like phpMyAdmin).

Bottom Line
Root cause analysis is much simpler now.


Keep Performing,
Moshe Kaplan