单条剖析查询 SHOW PROFILE

SHOW PROFILE命令式在mysql 5.1版本引入进来的，系统默认是禁用的，但能通过服务器变量在会话级别动态修改。

mysql> set profiling =1 ;
Query OK, 0 rows affected (0.00 sec)

然后，在服务器上执行的所有sql语句，都会测量其耗费的时间和一些查询执行状态变更的相关数据。
当提交一条查询给服务器是，这个工具会记录剖析信息到一张临时表，并且赋予一个从1开始的整数下标符。

mysql> select * from user;
7 rows in set (0.01 sec)
mysql> show profiles; 
+----------+------------+--------------------+
| Query_ID | Duration   | Query              |
+----------+------------+--------------------+
|        1 | 0.00682775 | select * from user |
+----------+------------+--------------------+
1 row in set (0.01 sec)

很准确的返回了查询时间，当然对于我们这些信息是不够的。

mysql> show profile for query 1;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000919 |
| Waiting for query cache lock   | 0.000019 |
| checking query cache for query | 0.000165 |
| checking permissions           | 0.000032 |
| Opening tables                 | 0.000089 |
| System lock                    | 0.000048 |
| init                           | 0.000108 |
| optimizing                     | 0.000025 |
| statistics                     | 0.000096 |
| preparing                      | 0.000035 |
| executing                      | 0.000016 |
| Sending data                   | 0.000268 |
| end                            | 0.000019 |
| query end                      | 0.000016 |
| closing tables                 | 0.000023 |
| freeing items                  | 0.004905 |
| logging slow query             | 0.000029 |
| cleaning up                    | 0.000019 |
+--------------------------------+----------+
18 rows in set (0.00 sec)

剖析报告按照执行顺序准确的告诉了我们每个步骤所消耗的时间，但我们很难快速一眼看出最大开销在哪儿。下面这段语句可以给出我们想要的结果视图。

mysql> set @query_id =1 ;
Query OK, 0 rows affected (0.00 sec)

mysql> 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 pcr_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  | pcr_r | Calls | R/Call       |
+--------------------------------+----------+-------+-------+--------------+
| freeing items                  | 0.004905 | 71.81 |     1 | 0.0049050000 |
| starting                       | 0.000919 | 13.45 |     1 | 0.0009190000 |
| Sending data                   | 0.000268 |  3.92 |     1 | 0.0002680000 |
| checking query cache for query | 0.000165 |  2.42 |     1 | 0.0001650000 |
| init                           | 0.000108 |  1.58 |     1 | 0.0001080000 |
| statistics                     | 0.000096 |  1.41 |     1 | 0.0000960000 |
| Opening tables                 | 0.000089 |  1.30 |     1 | 0.0000890000 |
| System lock                    | 0.000048 |  0.70 |     1 | 0.0000480000 |
| preparing                      | 0.000035 |  0.51 |     1 | 0.0000350000 |
| checking permissions           | 0.000032 |  0.47 |     1 | 0.0000320000 |
| logging slow query             | 0.000029 |  0.42 |     1 | 0.0000290000 |
| optimizing                     | 0.000025 |  0.37 |     1 | 0.0000250000 |
| closing tables                 | 0.000023 |  0.34 |     1 | 0.0000230000 |
| end                            | 0.000019 |  0.28 |     1 | 0.0000190000 |
| cleaning up                    | 0.000019 |  0.28 |     1 | 0.0000190000 |
| Waiting for query cache lock   | 0.000019 |  0.28 |     1 | 0.0000190000 |
| query end                      | 0.000016 |  0.23 |     1 | 0.0000160000 |
| executing                      | 0.000016 |  0.23 |     1 | 0.0000160000 |
+--------------------------------+----------+-------+-------+--------------+
18 rows in set (0.01 sec)

很清楚看到freeing items是最耗时间的步骤了。