使用show profile分析单条查询

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时，就会很具有分析价值了。