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

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.

Share this post

Comments (13)

  • Peter Laursen

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

    February 20, 2012 at 9:52 am
  • 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.

    February 20, 2012 at 11:02 am
  • Shlomi Noach

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

    February 20, 2012 at 11:47 am
  • Baron Schwartz

    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.

    February 20, 2012 at 12:00 pm
  • Baron Schwartz

    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.

    February 20, 2012 at 12:01 pm
  • Baron Schwartz

    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!

    February 20, 2012 at 12:04 pm
  • Shlomi Noach

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

    February 20, 2012 at 12:11 pm
  • 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?

    May 10, 2012 at 12:04 am
  • Baron Schwartz

    I wasn’t aware of that problem. Maybe there is a bug filed on that will shed more light on workarounds.

    May 10, 2012 at 5:40 am
  • Peter Laursen

    There is this bug report:

    May 10, 2012 at 5:54 am