MySQL Server’s built-in profiling support
April 18, 2011 5 Comments
MySQL’s SHOW PROFILES
command and its profiling support is something that I can’t believe I hadn’t spotted before today.
It allows you to enable profiling for a session and then record performance information about the queries executed. It shows details of the different stages in the query execution (as usually displayed in the thread state output of SHOW PROCESSLIST
) and how long each of these stages took.
I’ll demonstrate using an example. First within our session we need to enable profiling, you should only do this in sessions that you want to profile as there’s some overhead in performing/recording the profiling information:
mysql> SET profiling=1; Query OK, 0 rows affected (0.00 sec)
Now let’s run a couple of regular SELECT queries
mysql> SELECT COUNT(*) FROM myTable WHERE extra LIKE '%zkddj%'; +----------+ | COUNT(*) | +----------+ | 0 | +----------+ 1 row in set (0.32 sec) mysql> SELECT COUNT(id) FROM myTable; +-----------+ | COUNT(id) | +-----------+ | 513635 | +-----------+ 1 row in set (0.00 sec)
Followed up with some stuff that we know’s going to execute a bit slower:
mysql> CREATE TEMPORARY TABLE foo LIKE myTable; Query OK, 0 rows affected (0.00 sec) mysql> INSERT INTO foo SELECT * FROM myTable; Query OK, 513635 rows affected (33.53 sec) Records: 513635 Duplicates: 0 Warnings: 0 mysql> DROP TEMPORARY TABLE foo; Query OK, 0 rows affected (0.06 sec)
Now we’ve run the queries let’s look at their summary with SHOW PROFILES
mysql> SHOW PROFILES; +----------+-------------+-------------------------------------------------------------------+ | Query_ID | Duration | Query | +----------+-------------+-------------------------------------------------------------------+ | 1 | 0.33174700 | SELECT COUNT(*) FROM myTable WHERE extra LIKE '%zkddj%' | | 2 | 0.00036600 | SELECT COUNT(id) FROM myTable | | 3 | 0.00087700 | CREATE TEMPORARY TABLE foo LIKE myTable | | 4 | 33.52952000 | INSERT INTO foo SELECT * FROM myTable | | 5 | 0.06431200 | DROP TEMPORARY TABLE foo | +----------+-------------+-------------------------------------------------------------------+ 5 rows in set (0.00 sec)
It’s not like any of those numbers are a surprise as we saw them from the client but it’s a handy record of the execution times and could easily be queried within an application just before the connection to a db is closed or e.g. at the end of the web request.
We can also dig deeper into each of the commands, let’s look at the first query we ran:
mysql> SHOW PROFILE FOR QUERY 1; +--------------------------------+----------+ | Status | Duration | +--------------------------------+----------+ | starting | 0.000033 | | checking query cache for query | 0.000073 | | Opening tables | 0.000013 | | System lock | 0.000007 | | Table lock | 0.000035 | | init | 0.000032 | | optimizing | 0.000014 | | statistics | 0.000016 | | preparing | 0.000014 | | executing | 0.000009 | | Sending data | 0.331296 | | end | 0.000016 | | end | 0.000003 | | query end | 0.000005 | | storing result in query cache | 0.000105 | | freeing items | 0.000012 | | closing tables | 0.000007 | | logging slow query | 0.000003 | | logging slow query | 0.000048 | | cleaning up | 0.000006 | +--------------------------------+----------+ 20 rows in set (0.00 sec)
Looks like almost all of the time there was spent executing the query, definitely one worth investigating further with EXPLAIN
Now let’s look at the slow INSERT sub-select we ran to see what took the time. I’ve enabled CPU profiling here too.
mysql> SHOW PROFILE CPU FOR QUERY 4; +----------------------+-----------+-----------+------------+ | Status | Duration | CPU_user | CPU_system | +----------------------+-----------+-----------+------------+ | starting | 0.000069 | 0.000000 | 0.000000 | | checking permissions | 0.000010 | 0.000000 | 0.000000 | | Opening tables | 0.000217 | 0.000000 | 0.000000 | | System lock | 0.000006 | 0.000000 | 0.000000 | | Table lock | 0.000014 | 0.000000 | 0.000000 | | init | 0.000041 | 0.000000 | 0.000000 | | optimizing | 0.000007 | 0.000000 | 0.000000 | | statistics | 0.000014 | 0.000000 | 0.000000 | | preparing | 0.000013 | 0.000000 | 0.000000 | | executing | 0.000006 | 0.000000 | 0.000000 | | Sending data | 4.326303 | 3.544221 | 0.324020 | | Creating index | 0.000029 | 0.000000 | 0.000000 | | Repair by sorting | 29.202254 | 17.133071 | 11.616726 | | Saving state | 0.000040 | 0.000000 | 0.000000 | | Creating index | 0.000007 | 0.000000 | 0.000000 | | Sending data | 0.000389 | 0.000000 | 0.000000 | | end | 0.000009 | 0.000000 | 0.000000 | | end | 0.000012 | 0.000000 | 0.000000 | | query end | 0.000006 | 0.000000 | 0.000000 | | freeing items | 0.000015 | 0.000000 | 0.000000 | | closing tables | 0.000007 | 0.000000 | 0.000000 | | logging slow query | 0.000005 | 0.000000 | 0.000000 | | logging slow query | 0.000040 | 0.000000 | 0.000000 | | cleaning up | 0.000007 | 0.000000 | 0.000000 | +----------------------+-----------+-----------+------------+ 24 rows in set (0.00 sec)
It seems that building the indexes for the new table were what took the time. The General Thread States page of the MySQL Documentation is a useful reference. Interestingly we can see the “logging slow query” state here too, something that sails by too quickly to ever see when looking at SHOW PROCESSLIST
output.
This profiling support doesn’t fulfil the same role as MySQL’s EXPLAIN
command and is only useful in some places but if you were to look at implementing profiling or instrumentation for your app this could be really handy.
You can find the full documentation for MySQL’s profiling support at SHOW PROFILES Syntax it appears to be supported from at least MySQL 5.0 and it’s worth noting is only available in the MySQL Community (non-Enterprise) builds.