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

Share this post

Comments (13)

  • Peter Laursen Reply

    @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 Reply

    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 Reply

    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 Reply

    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 Reply

    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 Reply

    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 Reply

    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 Reply

    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 Reply

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

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

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

    May 10, 2012 at 5:54 am
  • Shlomi Noach Reply

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

    September 4, 2012 at 12:39 am
  • James Reply

    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?

    September 26, 2012 at 2:12 pm
  • ku Reply

    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

    May 22, 2017 at 12:38 am

Leave a Reply