Mysql剖析单条查询(高性能mySql学习笔记)

Mysql剖析单条查询的方法: (以mysql官网提供的sakila数据库演示)

方式1.通过show profile工具(show profile是Mysql5.1版本之后引入的功能)

工作原理：show profile是一个工具, 当一条查询提交给服务器时,该工具会将记录剖析信息到一张临时表，并且给查询赋予一个从1开始的整数标志符.

使用举例：

  Mysql> SET profiling=1; (默认是禁用的)

  Mysql>SELECT * from  sakila.nicer_but_slower_film_list;

  Mysql> show profiles;
+----------+------------+--------------------------------------------------+
| Query_ID | Duration   | Query                                            |
+----------+------------+--------------------------------------------------+
|        1 | 0.12766825 | SELECT * from  sakila.nicer_but_slower_film_list |
+----------+------------+--------------------------------------------------+

可以看到该语句执行时间,但是不够详细,此时可以使用 show profile for query queryId进一步查看更加详细的

mysql> show profile for query 1;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 7.5E-5   |
| checking permissions | 5E-6     |
| Opening tables       | 0.000431 |
| System lock          | 1.5E-5   |
| checking permissions | 2E-6     |
| checking permissions | 2E-6     |
| checking permissions | 1E-6     |
| checking permissions | 1E-6     |
| checking permissions | 0.002143 |
| optimizing           | 1.6E-5   |
| statistics           | 7.3E-5   |
| preparing            | 1.8E-5   |
| Creating tmp table   | 0.001932 |
| executing            | 4E-6     |
| Copying to tmp table | 0.052056 |
| Sorting result       | 0.008785 |
| Sending data         | 0.05388  |
| removing tmp table   | 0.002344 |
| Sending data         | 1.3E-5   |
| init                 | 1.8E-5   |
| optimizing           | 4E-6     |
| statistics           | 8E-6     |
| preparing            | 1E-5     |
| executing            | 1E-6     |
| Sending data         | 0.003856 |
| end                  | 9E-6     |
| query end            | 5E-6     |
| closing tables       | 2E-6     |
| removing tmp table   | 0.001827 |
| closing tables       | 1.8E-5   |
| freeing items        | 1.3E-5   |
| removing tmp table   | 7E-6     |
| freeing items        | 9E-5     |
| logging slow query   | 3E-6     |
| cleaning up          | 5E-6     |
+----------------------+----------+
35 rows in set

这个剖析报告给出了查询中每个步骤所花费的时间,但是这个报告是按照执行顺序进行排序的,但是我们更多的是关注花费时间最多的步骤, 此时我们如果不用show profile命令,还可以查询information_schema.PROFILING表

Mysql>SET @query_id = 9;

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 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.053959 | 44.97 |     3 | 0.0179863333 |
| Copying to tmp table | 0.048336 | 40.29 |     1 | 0.0483360000 |
| Sorting result       | 0.008770 | 7.31  |     1 | 0.0087700000 |
| removing tmp table   | 0.004025 | 3.35  |     3 | 0.0013416667 |
| checking permissions | 0.002216 | 1.85  |     6 | 0.0003693333 |
| Creating tmp table   | 0.001866 | 1.56  |     1 | 0.0018660000 |
| Opening tables       | 0.000437 | 0.36  |     1 | 0.0004370000 |
| freeing items        | 0.000094 | 0.08  |     2 | 0.0000470000 |
| starting             | 0.000079 | 0.07  |     1 | 0.0000790000 |
| statistics           | 0.000072 | 0.06  |     2 | 0.0000360000 |
| preparing            | 0.000022 | 0.02  |     2 | 0.0000110000 |
| optimizing           | 0.000021 | 0.02  |     2 | 0.0000105000 |
| System lock          | 0.000020 | 0.02  |     1 | 0.0000200000 |
| closing tables       | 0.000018 | 0.02  |     2 | 0.0000090000 |
| init                 | 0.000016 | 0.01  |     1 | 0.0000160000 |
| end                  | 0.000008 | 0.01  |     1 | 0.0000080000 |
| executing            | 0.000006 | 0.01  |     2 | 0.0000030000 |
| query end            | 0.000004 | 0.00  |     1 | 0.0000040000 |
| cleaning up          | 0.000004 | 0.00  |     1 | 0.0000040000 |
| logging slow query   | 0.000003 | 0.00  |     1 | 0.0000030000 |

从这个结果可以看到,sending data和Copying to tmp table花费时间最多,就可以进一步分析优化了.

方式2.通过show status方式剖析单条查询

原理:

show status大部分结果都只是一个计数器,可以显示某些活动如读索引的频繁程度,但无法给出消耗了多长时间.
尽管show status无法提供基于时间的统计,但是执行完成后观察执行结果,还是 有帮助的,最有用的计数器包括:
句柄计数器(handler counter),临时文件,表计数器
我们可以通过将会话级别的计数器清零,然后查询前面的视图,再检查计数器结果

mysql> FLUSH statu;
mysql> SELECT * from nicer_but_slower_film_list;

mysql> show status where Variable_name like 'Handler%' or Variable_name Like 'Created%';

+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Created_tmp_disk_tables    | 10    |
| Created_tmp_files          | 5     |
| Created_tmp_tables         | 28    |
| Handler_commit             | 5     |
| Handler_delete             | 0     |
| Handler_discover           | 0     |
| Handler_prepare            | 0     |
| Handler_read_first         | 5     |
| Handler_read_key           | 37425 |
| Handler_read_last          | 0     |
| Handler_read_next          | 32310 |
| Handler_read_prev          | 0     |
| Handler_read_rnd           | 27330 |
| Handler_read_rnd_next      | 37788 |
| Handler_rollback           | 0     |
| Handler_savepoint          | 0     |
| Handler_savepoint_rollback | 0     |
| Handler_update             | 15    |
| Handler_write              | 37664 |
+----------------------------+-------+

从这个结果可以看到,该查询创建了10张磁盘临时表, 而且有很多没有用到索引的多操作(Handler_read_rnd_next),假设我们不知道该视图的结构,仅从结果我们可以推测到该视图使用了多表关联查询,而且没有使用合适的索引,可能是其中一个子查询创建了临时表,和其他表做关联查询, 而保存子查询结果的临时表没有合适的索引.

注意：通过explain 命令也可以得到大部分结果，但是explain是通过估计得到的结果,而通过计数器则是实际的测量结果.