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 2 3 4 |
mysql> SET profiling=1; mysql> pager cat > /dev/null mysql> SELECT * FROM nicer_but_slower_film_list; 997 rows in set (0.18 sec) |
The query consumed 0.18 seconds. Where did the time go?
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
mysql> SHOW PROFILE FOR QUERY 1; +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.000032 | | checking permissions | 0.000005 | ... snip ... | init | 0.000021 | | optimizing | 0.000003 | | statistics | 0.000006 | | cleaning up | 0.000003 | +----------------------+----------+ 35 rows in set (0.00 sec) |
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 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 28 29 30 31 32 33 34 35 36 37 38 39 40 41 |
SET @query_id := 1; SELECT STATE, SUM(DURATION) AS Total_R, ROUND( 100 * SUM(DURATION) / (SELECT SUM(DURATION) FROM INFORMATION_SCHEMA.PROFILING WHERE QUERY_ID = @query_id ), 2) AS Pct_R, COUNT(*) AS Calls, SUM(DURATION) / COUNT(*) AS "R/Call" FROM INFORMATION_SCHEMA.PROFILING WHERE QUERY_ID = @query_id GROUP BY STATE ORDER BY Total_R DESC; +----------------------+----------+-------+-------+--------------+ | STATE | Total_R | Pct_R | Calls | R/Call | +----------------------+----------+-------+-------+--------------+ | removing tmp table | 0.095135 | 55.10 | 3 | 0.0317116667 | | Copying to tmp table | 0.046175 | 26.74 | 1 | 0.0461750000 | | Sending data | 0.018478 | 10.70 | 3 | 0.0061593333 | | Sorting result | 0.011090 | 6.42 | 1 | 0.0110900000 | | checking permissions | 0.000802 | 0.46 | 6 | 0.0001336667 | | Creating tmp table | 0.000548 | 0.32 | 1 | 0.0005480000 | | Opening tables | 0.000196 | 0.11 | 1 | 0.0001960000 | | statistics | 0.000071 | 0.04 | 2 | 0.0000355000 | | starting | 0.000032 | 0.02 | 1 | 0.0000320000 | | freeing items | 0.000027 | 0.02 | 2 | 0.0000135000 | | preparing | 0.000025 | 0.01 | 2 | 0.0000125000 | | init | 0.000021 | 0.01 | 1 | 0.0000210000 | | optimizing | 0.000020 | 0.01 | 2 | 0.0000100000 | | closing tables | 0.000014 | 0.01 | 2 | 0.0000070000 | | System lock | 0.000010 | 0.01 | 1 | 0.0000100000 | | query end | 0.000003 | 0.00 | 1 | 0.0000030000 | | cleaning up | 0.000003 | 0.00 | 1 | 0.0000030000 | | executing | 0.000002 | 0.00 | 2 | 0.0000010000 | | end | 0.000002 | 0.00 | 1 | 0.0000020000 | | logging slow query | 0.000001 | 0.00 | 1 | 0.0000010000 | +----------------------+----------+-------+-------+--------------+ |
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.
