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.
Comments (13)
@Baron: Two comments:
1) Maybe I am missing something but isn’t the *lost time* (if you compare the SUM from SHOW PROFILE with the execution time displayed in command line client) due to the fact that the first are based on TIMESTAMPs sampled from the server and the latter from TIMESTAMPs sampled from the client (what could be running on different machines actually)?
2) You know the SQLyog ‘Query Proviler’ very well (you reviewed it before it was released). Is there any (significant difference between what ww/SQLyog do and what you do here (and the aggregation was OUR invention and decision at the time!)?
I don’t know if you have checked out my MyQuery query tool. It’s Windows only, but it does have some nifty features, like how it makes it real easy to work with profiling, like sorting and comparing the different profiles of two queries with just a few clicks.
Cool. This calls for a new view (or set of views) on common_schema (though no plug intended)
Shlomi: I thought about that, but hadn’t gotten around to sending you email yet. No need now 🙂
Anders: I don’t use Windows much, and graphical tools even less often, but that sounds nice.
Peter: 1) not necessarily; I am not referring to the execution time as seen by the client, but rather the real execution time on the server, which might be different from the sum of durations of stages (maybe not, though, but that’s the point of having a lost-time entry; c.f. Cary Millsap for more on this), and 2) it’s been a long time since I used SQLYog, so I’ve forgotten it, but it’s probably the same thing I’ve done here.
Shlomi, if you want to add a lost-time entry, note that the output of SHOW PROFILES has a Duration column that might be possible to read in your usual tricky ways 🙂 there’s just no corresponding I_S table.
To illustrate more what I mean about lost time, the slow query log shows 0.166872 seconds for the sample of this I use in the book, and SHOW PROFILES has 0.16767900 seconds. This is an example of incomplete profiling: SHOW PROFILES measures the time taken in logging the slow query and “finishing up” and so on, but obviously the slow query log won’t capture any work that’s done after the query is written to the log!
Baron, alas, tricky way will not work here as SHOW PROFILES do not accept a WHERE or LIKE extension.
Thanks for the post. A newbie comment here, I noticed that the inclusion of a function (user defined) in a query excludes it from PROFILES. Any workaround?
I wasn’t aware of that problem. Maybe there is a bug filed on bugs.mysql.com that will shed more light on workarounds.
There is this bug report:
http://bugs.mysql.com/bug.php?id=61328
A similar solution is now available in common_schema: last_query_profiling.html
I have a update query, it take long time. when check the profiler, I find the init state has almost all the time, what does it mean?
Hello Baron
I need to know how to output QUERY TEXT in your example instead of QUERYID. I need to know it because I have almoast 30 queries running starting from midnight, and then need to check profiling. Can you help me?
Jakub