"SHOW PROFILE" - Query Profiling

MySQL Tutorials - Herong's Tutorial Examples

∟"SHOW PROFILE" - Query Profiling

This section provides a tutorial example on how to use the Query Profiling tool provided in MySQL server to figure out which steps of a query statement taking more execution time than others.

What Is Query Profiling? Query profiling is a performance tuning tool provided by MySQL server that allows you to see resource usage profiles of a given query.

Here are the main steps to use the query profiling tool.

Turn on query Profiling with "SET SESSION profiling = 1".
Run MySQL statements that you want to profile.
View a list of profiled statements with their execution times with "SHOW PROFILES"
View profiling details of a given statement with "SHOW PROFILE CPU, BLOCK IO, PAGE FAULTS, SWAP FOR QUERY n"

Here is what I did to use the query profiling tool to look at the INSERT statement performance issue reported in the previous tutorial.

1. Connect to my CentOS MySQL server and create the the "Tests" table again.

mysql> CREATE TABLE Tests (Quantity INTEGER);

2. Turn on query profiling and run some INSERT statements:

mysql> SET SESSION profiling = 1

mysql> INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000));
Query OK, 1 row affected (0.06 sec)

mysql> INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000));
Query OK, 1 row affected (0.05 sec)

mysql> INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000));
Query OK, 1 row affected (0.06 sec)

3. Get a list of profiled queries. The average of execution time is about still about 55 ms.

mysql> SHOW PROFILES;

Query_ID Duration   Query
-------- ---------- -----------------------------------------------
       1 0.05487575 INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000))
       2 0.04755650 INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000))
       3 0.06314350 INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000))
       4 0.01896000 SHOW PRFILES

4. Get Profiling details on the third query:

mysql> SHOW PROFILE CPU, BLOCK IO, PAGE FAULTS, SWAPS FOR QUERY 3;

Status                        Duration CPU_user/system   Block_in/0ut P_F_major/minor Swaps
----------------------------- -------- --------/-------- --------/--- ---------/----- -----
starting                      0.000059 0.000052/0.000006        0/  0         0/    0     0
Executing hook on transaction 0.000004 0.000004/0.000001        0/  0         0/    0     0
starting                      0.000006 0.000006/0.000000        0/  0         0/    0     0
checking permissions          0.000005 0.000004/0.000001        0/  0         0/    0     0
Opening tables                0.000022 0.000020/0.000002        0/  0         0/    0     0
init                          0.000007 0.000006/0.000001        0/  0         0/    0     0
System lock                   0.000007 0.000006/0.000000        0/  0         0/    0     0
update                        0.000056 0.000051/0.000006        0/  0         0/    0     0
end                           0.000004 0.000003/0.000000        0/  0         0/    0     0
query end                     0.000003 0.000003/0.000001        0/  0         0/    0     0
waiting for handler commit    0.062925 0.000161/0.002778        0/ 40         0/    0     0
closing tables                0.000020 0.000018/0.000002        0/  0         0/    0     0
freeing items                 0.000018 0.000016/0.000002        0/  0         0/    0     0
cleaning up                   0.000008 0.000007/0.000000        0/  0         0/    0     0

Now I know which step is taking most of the execution time: "waiting for handler commit". So this state waited for 63 ms to commit due to 40 blocked output IO operations.