show profile命令是Mysql5.1版本中引入的,默认是禁用的,但可以通过服务器变量在会话级别动态地修改,下面是打开profile:
mysql> set profiling = 1;
Query OK, 0 rows affected (0.00 sec)
执行下show profile查看最近执行的查询情况:
mysql> show profiles;
+----------+------------+--------------------------+
| Query_ID | Duration | Query |
+----------+------------+--------------------------+
| 1 | 0.00134600 | show tables |
| 2 | 0.01328775 | select * from AASC |
| 3 | 0.00020075 | select * from AAASTUDENT |
| 4 | 0.00029550 | select * from AASTUDENT |
| 5 | 0.00019100 | select * from AATECHER |
| 6 | 0.00022300 | select * from AATEACHER |
+----------+------------+--------------------------+
6 rows in set (0.00 sec)
从上面的结果可以看出,以很高的精度显示了查询时间
细信息查看,按下面的方式执行即可:
mysql> show profile for query 1;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000034 |
| checking permissions | 0.000006 |
| Opening tables | 0.000012 |
| System lock | 0.000005 |
| init | 0.000014 |
| optimizing | 0.000003 |
| statistics | 0.000008 |
| preparing | 0.000005 |
| executing | 0.000001 |
| Sending data | 0.000077 |
| end | 0.000004 |
| query end | 0.000003 |
| closing tables | 0.000005 |
| freeing items | 0.000043 |
| logging slow query | 0.000003 |
| cleaning up | 0.000002 |
+----------------------+----------+
16 rows in set (0.00 sec)
虽然详细,但是很难直接看出性能问题,加入不使用show profile命令,而是直接查询information_schema中对应的表,则可以按需格式化输出:
mysql> set @query_id = 1;
Query OK, 0 rows affected (0.00 sec)
SELECT STATE
,sum(duration) AS total_r
,round(100 * sum(duration) / (
SELECT sum(duration)
FROM information_schemling
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 |
+----------------------+----------+-------+-------+--------------+
| Sending data | 0.000077 | 34.22 | 1 | 0.0000770000 |
| freeing items | 0.000043 | 19.11 | 1 | 0.0000430000 |
| starting | 0.000034 | 15.11 | 1 | 0.0000340000 |
| init | 0.000014 | 6.22 | 1 | 0.0000140000 |
| Opening tables | 0.000012 | 5.33 | 1 | 0.0000120000 |
| statistics | 0.000008 | 3.56 | 1 | 0.0000080000 |
| checking permissions | 0.000006 | 2.67 | 1 | 0.0000060000 |
| System lock | 0.000005 | 2.22 | 1 | 0.0000050000 |
| preparing | 0.000005 | 2.22 | 1 | 0.0000050000 |
| closing tables | 0.000005 | 2.22 | 1 | 0.0000050000 |
| end | 0.000004 | 1.78 | 1 | 0.0000040000 |
| logging slow query | 0.000003 | 1.33 | 1 | 0.0000030000 |
| query end | 0.000003 | 1.33 | 1 | 0.0000030000 |
| optimizing | 0.000003 | 1.33 | 1 | 0.0000030000 |
| cleaning up | 0.000002 | 0.89 | 1 | 0.0000020000 |
| executing | 0.000001 | 0.44 | 1 | 0.0000010000 |
+----------------------+----------+-------+-------+--------------+
16 rows in set (0.07 sec)
从上面的查询结果可以看出来,发送数据和释放索引消耗的时间较多,但这属于正常开销,如果以后执行复杂的SQL时,就会很具有分析价值了。