MySQL Profiling

by kiawin

If we ever wondered what’s the performance of a MySQL query and a SELECT query be more efficient (and hence faster)?

MySQL has an embedded profiling feature that we can use from stock MySQL.

To enable it, it’s pretty simple:

mysql> SET profiling = 1;

You may perform whatever queries you would like to do. At the end of the session, just go ahead and type this:

mysql> SHOW PROFILES;

You will see an informative table filled with the duration taken to perform the individual queries.

+----------+----------+--------------------------+
| Query_ID | Duration | Query                    |
+----------+----------+--------------------------+
|        0 | 0.000088 | SET PROFILING = 1        |
|        1 | 0.000136 | DROP TABLE IF EXISTS t1  |
|        2 | 0.011947 | CREATE TABLE t1 (id INT) |
+----------+----------+--------------------------+
3 rows in set (0.00 sec)

Most importantly, we can view how much time breakdown taken by MySQL to perform these (all) operations by using SHOW PROFILE;

mysql> SHOW PROFILE;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| checking permissions | 0.000040 |
| creating table       | 0.000056 |
| After create         | 0.011363 |
| query end            | 0.000375 |
| freeing items        | 0.000089 |
| logging slow query   | 0.000019 |
| cleaning up          | 0.000005 |
+----------------------+----------+
7 rows in set (0.00 sec)

The above command is essential as we can identify the bottleneck of the operation. This is evidently useful when we compare two different table schema, one unoptimized and another optimized. For example, adding KEY to enable indexing for SELECT.

If you wish to dig in further with individual query, you may use SHOW PROFILE FOR QUERY 1;

mysql> SHOW PROFILE FOR QUERY 1;
+--------------------+----------+
| Status             | Duration |
+--------------------+----------+
| query end          | 0.000107 |
| freeing items      | 0.000008 |
| logging slow query | 0.000015 |
| cleaning up        | 0.000006 |
+--------------------+----------+
4 rows in set (0.00 sec)

You can even check CPU load by SHOW PROFILE CPU FOR QUERY 2;

mysql> SHOW PROFILE CPU FOR QUERY 2;
+----------------------+----------+----------+------------+
| Status               | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| checking permissions | 0.000040 | 0.000038 |   0.000002 |
| creating table       | 0.000056 | 0.000028 |   0.000028 |
| After create         | 0.011363 | 0.000217 |   0.001571 |
| query end            | 0.000375 | 0.000013 |   0.000028 |
| freeing items        | 0.000089 | 0.000010 |   0.000014 |
| logging slow query   | 0.000019 | 0.000009 |   0.000010 |
| cleaning up          | 0.000005 | 0.000003 |   0.000002 |
+----------------------+----------+----------+------------+
7 rows in set (0.00 sec)

The profiling session only valid for each session, hence you may either exit the console or disable it manually by SET profiling = 0;.

All these information is freely available on MySQL documentation and visit it for more details.

Happy Profiling :)