MySQL之性能剖析(三)

剖析MySQL查询

剖析单条查询

在定位到需要优化的单条查询后，可以针对查询"钻取"更多的信息，确认为什么会花费这么长的时间执行，以及需要如何去优化。不幸的是，MySQL目前大多数的测量点对于剖析查询都没有什么帮助。当然这种状况正在改善，大多数生产环境的服务器还没有使用包含最新剖析特性的版本。所以在实际应用中，除了SHOW STATUS、SHOW PROFILE、检查慢查询日志的条目(这还要求必须是Percona Server,官方MySQL版本的慢查询缺失了很多附加信息)这三种方法外就没有什么更好的办法了。

使用SHOW PROFILE

SHOW PROFILE命令是在MySQL 5.1以后的版本中引入的，来源于开源社区中的Jeremy Cole的贡献。这是唯一一个在GA版本中包含的真正的查询剖析工具。默认是禁用地，还可以通过服务器变量在会话(连接)级别动态地修改。

mysql> SELECT VERSION();
+------------+
| VERSION()  |
+------------+
| 5.7.42-log |
+------------+
1 row in set (0.11 sec)mysql> SHOW VARIABLES LIKE 'profiling';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| profiling     | OFF   |
+---------------+-------+
1 row in set (0.07 sec)mysql> SHOW PROFILE-> ;
Empty set

然后再服务器上执行的所有语句，都会测量其耗费的时间和其他一些查询执行状态变更相关的数据。这个功能有一定的作用，而且最初的设计功能更强大，但未来版本中可能会被Performance Schema所取代，尽管如此，这个工具最有用的作用还是在语句执行期间剖析服务器的具体工作。
当一条查询提交给服务器时，此工具会记录剖析信息到一张临时表，并且给查询赋予一个从1开始的整数标识符。

例子

举个例子

mysql> SELECT * FROM chat_room ORDER BY id DESC LIMIT 10;
10 rows in set (0.18 sec)
mysql> SHOW PROFILES;
+----------+------------+-------------------------------------------------------+
| Query_ID | Duration   | Query                                                 |
+----------+------------+-------------------------------------------------------+
|        1 | 0.00397750 | SHOW VARIABLES LIKE 'profiling'                       |
|        2 | 0.00010750 | SELECT * FROM chat ORDER BY id DESC LIMIT 100         |
|        3 | 0.00010100 | use chat                                              |
|        4 | 0.00020625 | SELECT * FROM chat ORDER BY id DESC LIMIT 100         |
|        5 | 0.15971150 | SELECT * FROM chat_message ORDER BY id DESC LIMIT 100 |
|        6 | 0.00036200 | SELECT * FROM chat_message ORDER BY id DESC LIMIT 10  |
|        7 | 0.00037850 | SELECT * FROM chat_room ORDER BY id DESC LIMIT 10     |
+----------+------------+-------------------------------------------------------+
7 rows in set (0.17 sec)

该查询返回了10行记录，花费了0.18秒。接下来是SHOW PROFILES。
首先可以看到的是以很高的精度显示了查询的响应时间，这很好。MySQL客户端显示的时间只有两位小数，对于一些执行得很快的查询这样的精度是不够的。接下来继续看接下来的输出:


mysql> SHOW PROFILE FOR QUERY 7;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000077 |
| checking permissions | 0.000007 |
| Opening tables       | 0.000071 |
| init                 | 0.000016 |
| System lock          | 0.000006 |
| optimizing           | 0.000003 |
| statistics           | 0.000008 |
| preparing            | 0.000009 |
| Sorting result       | 0.000003 |
| executing            | 0.000002 |
| Sending data         | 0.000123 |
| end                  | 0.000004 |
| query end            | 0.000005 |
| closing tables       | 0.000005 |
| freeing items        | 0.000024 |
| cleaning up          | 0.000016 |
+----------------------+----------+
16 rows in set (0.17 sec)

剖析报告给出了查询执行的每个步骤及其花费的时间，看结果很难快速地确定哪个步骤花费地时间最多。因为输出是按照执行顺序排序，而不是按花费的时间排序的——而实际上我们更关心的是花费了多少多少时间，这样才能知道哪些开销比较打。但不幸的是无法通过诸如ORDER BY 之类的命令重新排序。假如不适用SHOW PROFILE命令而是这届查询INFORMATION_SHCEMA中对应的表，则可以按照需要格式化输出
如下方所示

mysql> SET @query_id = 7;
mysql>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.000123 | 32.45 |     1 | 0.0001230000 |
| starting             | 0.000077 | 20.32 |     1 | 0.0000770000 |
| Opening tables       | 0.000071 | 18.73 |     1 | 0.0000710000 |
| freeing items        | 0.000024 | 6.33  |     1 | 0.0000240000 |
| init                 | 0.000016 | 4.22  |     1 | 0.0000160000 |
| cleaning up          | 0.000016 | 4.22  |     1 | 0.0000160000 |
| preparing            | 0.000009 | 2.37  |     1 | 0.0000090000 |
| statistics           | 0.000008 | 2.11  |     1 | 0.0000080000 |
| checking permissions | 0.000007 | 1.85  |     1 | 0.0000070000 |
| System lock          | 0.000006 | 1.58  |     1 | 0.0000060000 |
| closing tables       | 0.000005 | 1.32  |     1 | 0.0000050000 |
| query end            | 0.000005 | 1.32  |     1 | 0.0000050000 |
| end                  | 0.000004 | 1.06  |     1 | 0.0000040000 |
| Sorting result       | 0.000003 | 0.79  |     1 | 0.0000030000 |
| optimizing           | 0.000003 | 0.79  |     1 | 0.0000030000 |
| executing            | 0.000002 | 0.53  |     1 | 0.0000020000 |
+----------------------+----------+-------+-------+--------------+
16 rows in set (0.17 sec)

效果好多了，通过这个结果可以很容易看到查询时间太长主要是因为花了一大半的时间是"发送数据(Sending data)“，这个状态代表的原因非常多，可能是各种不同的服务器活动，包括在关联时搜索匹配的行记录等，这部分很难说能优化节省多少消耗时间。还有一种可能导致查询时间太长的原因，是数据复制到临时表这一步。如果是这种情况，则就要考虑如何改写查询以避免使用临时表，或者提升临时表的使用效率，另外还有一种状态是"结果排序()Sorting result”，如果花费的时间占比非常低。那这部分是不值得去优化的。这是一个比较典型的问题，所以一般我们都不建议用户在"优化排序缓冲区(tunning sort buffer)"或者类似的活动上花时间。
尽管剖析报告帮助我们定位到哪些活动花费了最多的时间，但并不会告诉我们为什么会这样，要弄清除为什么状态花费这么多时间，就需要深入下去，继续剖析这一步的子任务。

使用SHOW STATUS

MySQL的SHOW STATUS命令返回了一些计数器。既有服务器级别的全局计数器，也有基于某个连接的会话级别的计数器。例如其中的Queries在会话开始时为0，每提交一条查询增加1.如果执行SHOW GLOBAL STATUS(注意到新加额GLOBAL关键字)，则可以查看服务器级别的从服务器启动时开始计算的查询次数统计。不同计数器的可见范围不一样，不过全局的计数器也会出现SHOW STATUS的结果中，容易被误认为时会话级别的，千万不要搞迷糊了。在使用这个命令时要注意几点，就像前面所讨论的，收集合适级别的测量值是很关键的。如果打算优化从某些特定连接观察到的东西，测量的却是全局级别的数据，就会导致胡乱.MySQL官方手册中对所有变量是会话级还是全局级做了详细的说明。
SHOW STATUS是一个有用的工具，但并不是一款剖析工具。SHOW STATUS的大部分结果都只是一个计数器，可以显示某些互动如读索引的频繁程度，但无法给出消耗了多少时间。SHOW STATUS的结果中只有一条指的是操作时间(Innodb_row_lock_time)，而且只能是全局级的，所以还是无法测量绘画级别的工作。尽管SHOW STATUS无法提供基于时间的统计，但对于在执行完查询后观察某些计数器的值还是有帮助的。有时候可以猜测哪些操作代价较高或者消耗的时间较多。最有用的计数器包括句柄计数器(handler counter)、临时文件和表计数器等。下面的例子演示了如何将会话级别的计数器重置为0，然后查询前面(SHOW PROFILE)提到的视图,再检查计数器的结果

例子

举个例子

mysql> FLUSH STATUS;
Query OK, 0 rows affected (0.09 sec)mysql> SELECT * FROM chat_room ORDER BY id DESC LIMIT 10;
10 rows in set (0.15 sec)
mysql> SHOW STATUS WHERE Variable_name LIKE '%Handler%' OR Variable_name LIKE 'Created%';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Created_tmp_disk_tables    | 0     |
| Created_tmp_files          | 0     |
| Created_tmp_tables         | 0     |
| Handler_commit             | 1     |
| Handler_delete             | 0     |
| Handler_discover           | 0     |
| Handler_external_lock      | 2     |
| Handler_mrr_init           | 0     |
| Handler_prepare            | 0     |
| Handler_read_first         | 0     |
| Handler_read_key           | 1     |
| Handler_read_last          | 1     |
| Handler_read_next          | 0     |
| Handler_read_prev          | 9     |
| Handler_read_rnd           | 0     |
| Handler_read_rnd_next      | 0     |
| Handler_rollback           | 0     |
| Handler_savepoint          | 0     |
| Handler_savepoint_rollback | 0     |
| Handler_update             | 0     |
| Handler_write              | 0     |
+----------------------------+-------+
21 rows in set (0.19 sec)

从结果中可以看到Created_tmp_tables创建临时表的次数。以及读取记录的前一个指针Handler_read_prev的次数。仅从结果来推测，我们可以判断出，上面的SELECT查询在找到最新一条行记录时，通过读取前一个节点指针来获取记录的。

使用这个技术的时候，要注意SHOW STATUS本身也会创建一个临时表，而且也会通过句柄操作访问此临时表，这会影响到SHOW STATUS结果中对应的数字，而且不同的版本可能行为也不尽相同。
你可能会注意到通过EXPLAIN 查询查询的执行计划也可以获得大部分相同的信息，但EXPLAIN是通过估计得到的结果，而通过计数器则是实际的测量结果。例如EXPLAIN 无法告诉你临时表是否是磁盘表，这和内存临时表的性能差别是很大的。