The Query Profiler in MySQL isn’t something I’ve spent much time in recently – with more sites making use of popular CMSes like WordPress, query performance isn’t something that’s top of mind anymore (Automatic seems to do a good job in this area). But it’s still a useful tool when you’ve already picked the low hanging fruit off of the optimization tree.
Profiling is enabled on an individual basis for each MySQL session; when the session ends, all profiling information is lost.
To check to see if profiling is currently enabled for your session, do:
1 2 3 4 5 6 7 | mysql> SELECT @@profiling;+-------------+| @@profiling |+-------------+| 0 |+-------------+1 row in set (0.00 sec) |
Next, enable profiling for all queries:
1 2 | mysql> SET profiling = 1;Query OK, 0 rows affected (0.00 sec) |
And run the query you’d like to see a breakdown for:
1 2 3 4 5 6 7 | mysql> SELECT COUNT(*) FROM wp_posts;+----------+| count(*) |+----------+| 238121 |+----------+1 row in set (18.80 sec) |
Get the numeric ID of the profile we want to see:
1 2 3 4 5 6 7 | mysql> SHOW PROFILES;+----------+----------+---------------------------------------+| Query_ID | Duration | Query |+----------+----------+---------------------------------------+| 1 | 18.80000 | SELECT COUNT(*) FROM wp_posts; |+----------+----------+---------------------------------------+1 row in set (0.00 sec) |
Finally, actually see the query profiled:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 | mysql> SHOW PROFILE FOR QUERY 1;+--------------------------------+-----------+| Status | Duration |+--------------------------------+-----------+| starting | 0.000027 || checking query cache for query | 0.000041 || checking permissions | 0.000017 || Opening tables | 0.000018 || System lock | 0.000008 || Table lock | 0.000037 || init | 0.000014 || optimizing | 0.000008 || statistics | 0.000016 || preparing | 0.000013 || executing | 0.000008 || Sending data | 18.802902 || end | 0.000015 || end | 0.000008 || query end | 0.000006 || storing result in query cache | 0.000453 || freeing items | 0.000009 || closing tables | 0.000007 || logging slow query | 0.000007 || logging slow query | 0.000031 || cleaning up | 0.000005 |+--------------------------------+-----------+21 rows in set (0.00 sec) |
To get even more in depth, check out the optional type values for the SHOW PROFILE command, or use SHOW PROFILE ALL FOR QUERY 1; and view everything MySQL’s got at once.