SHOW PROFILES shows how much time MySQL spends in various phases of query execution, but it isn’t a full-featured profile. By that, I mean that it doesn’t show similar phases aggregated together, doesn’t sort them by worst-first, and doesn’t show the relative amount of time consumed.
I’ll profile the “nicer_but_slower_film_list” included with the Sakila sample database to demonstrate:
|
1 |
mysql> SET profiling=1;<br>mysql> pager cat > /dev/null<br>mysql> SELECT * FROM nicer_but_slower_film_list;<br>997 rows in set (0.18 sec) |
The query consumed 0.18 seconds. Where did the time go?
|
1 |
mysql> SHOW PROFILE FOR QUERY 1;<br>+----------------------+----------+<br>| Status | Duration |<br>+----------------------+----------+<br>| starting | 0.000032 |<br>| checking permissions | 0.000005 |<br>... snip ...<br>| init | 0.000021 |<br>| optimizing | 0.000003 |<br>| statistics | 0.000006 |<br>| cleaning up | 0.000003 |<br>+----------------------+----------+<br>35 rows in set (0.00 sec)<br> |
It’s pretty hard to figure out what consumed the most time, because it’s sorted in execution order, not order of time consumption. Here is one query that can solve this partially:
|
1 |
<br>SET @query_id := 1;<br>SELECT STATE, SUM(DURATION) AS Total_R,<br> ROUND(<br> 100 * SUM(DURATION) /<br> (SELECT SUM(DURATION)<br> FROM INFORMATION_SCHEMA.PROFILING<br> WHERE QUERY_ID = @query_id<br> ), 2) AS Pct_R,<br> COUNT(*) AS Calls,<br> SUM(DURATION) / COUNT(*) AS "R/Call"<br> FROM INFORMATION_SCHEMA.PROFILING<br> WHERE QUERY_ID = @query_id<br> GROUP BY STATE <br> ORDER BY Total_R DESC; <br><br>+----------------------+----------+-------+-------+--------------+<br>| STATE | Total_R | Pct_R | Calls | R/Call |<br>+----------------------+----------+-------+-------+--------------+<br>| removing tmp table | 0.095135 | 55.10 | 3 | 0.0317116667 |<br>| Copying to tmp table | 0.046175 | 26.74 | 1 | 0.0461750000 |<br>| Sending data | 0.018478 | 10.70 | 3 | 0.0061593333 |<br>| Sorting result | 0.011090 | 6.42 | 1 | 0.0110900000 |<br>| checking permissions | 0.000802 | 0.46 | 6 | 0.0001336667 |<br>| Creating tmp table | 0.000548 | 0.32 | 1 | 0.0005480000 |<br>| Opening tables | 0.000196 | 0.11 | 1 | 0.0001960000 |<br>| statistics | 0.000071 | 0.04 | 2 | 0.0000355000 |<br>| starting | 0.000032 | 0.02 | 1 | 0.0000320000 |<br>| freeing items | 0.000027 | 0.02 | 2 | 0.0000135000 |<br>| preparing | 0.000025 | 0.01 | 2 | 0.0000125000 |<br>| init | 0.000021 | 0.01 | 1 | 0.0000210000 |<br>| optimizing | 0.000020 | 0.01 | 2 | 0.0000100000 |<br>| closing tables | 0.000014 | 0.01 | 2 | 0.0000070000 |<br>| System lock | 0.000010 | 0.01 | 1 | 0.0000100000 |<br>| query end | 0.000003 | 0.00 | 1 | 0.0000030000 |<br>| cleaning up | 0.000003 | 0.00 | 1 | 0.0000030000 |<br>| executing | 0.000002 | 0.00 | 2 | 0.0000010000 |<br>| end | 0.000002 | 0.00 | 1 | 0.0000020000 |<br>| logging slow query | 0.000001 | 0.00 | 1 | 0.0000010000 |<br>+----------------------+----------+-------+-------+--------------+<br> |
Much nicer. Now you can see that over 3/4ths of the time was spent working with temporary tables.
But there’s something still missing: it doesn’t show lost time (the amount of time not accounted by the profiling). That is, the SUM(DURATION) isn’t the same as the total query duration. Alas, there is no query-level table that would allow me to subtract the SUM(DURATION) from the query’s real response time. If there were, I could add in a UNION to inject another row for “lost time” and show the portion of response time that wasn’t captured in the profile.
The above query is something I developed for High Performance MySQL Third Edition, by the way. The book should be available in a matter of weeks.
Resources
RELATED POSTS
