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

by February 20, 2012 By Baron Schwartz 10 Comments

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:

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?

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:

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.