How to convert MySQL’s SHOW PROFILES into a real profile

PREVIOUS POST
NEXT POST

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.

PREVIOUS POST
NEXT POST

Comments

  1. says

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

  2. Anders Karlsson says

    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.

  3. says

    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.

  4. says

    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.

  5. says

    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!

  6. Henrik Janér says

    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?

  7. James says

    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?

Leave a Reply

Your email address will not be published. Required fields are marked *