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:

The query consumed 0.18 seconds. Where did the time go?

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:

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.

13 Comments
Oldest
Newest Most Voted
Inline Feedbacks
View all comments
Peter Laursen

: 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!)?

Anders Karlsson

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.

Shlomi Noach

Cool. This calls for a new view (or set of views) on common_schema (though no plug intended)

Shlomi Noach

Baron, alas, tricky way will not work here as SHOW PROFILES do not accept a WHERE or LIKE extension.

Henrik Janér

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?

Peter Laursen

There is this bug report:
http://bugs.mysql.com/bug.php?id=61328

Shlomi Noach

A similar solution is now available in common_schema: last_query_profiling.html

James

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?

ku

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