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是最耗时间的步骤了。