MySQL案例：一个有趣的慢查询问题分析
原创MySQL案例：一个有趣的慢查询问题分析
原创
前言
前几天，有位客户提了一个慢查询问题，需要这边帮忙分析一下；整个排查过程还是非常有趣，涉及到一些值得关注的知识点，因此在这里记录一下。
场景分析
（1）慢查询是一条简单的update语句：UPDATE xxx_order set status = 6 where order_no = 'xxx'，耗时30s，扫描行数1400w
（2）查看表结构，确认order_no列存在索引，不存在问题
CREATE TABLE `xxx_order` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`order_no` varchar(64) NOT NULL COMMENT '订单编号',
...
PRIMARY KEY (`id`),
...
KEY `idx_order_no_status` (`order_no`,`status`),
...
) ENGINE=InnoDB AUTO_INCREMENT=269006244 DEFAULT CHARSET=utf8mb4 COMMENT='xxx'（3）查看执行计划，走的执行计划是idx_order_no_status，不存在问题
（4）其实这个时候，我们会怀疑，当时走的执行计划究竟是什么样的？MySQL没有类似Oracle存储ASH和历史执行计划等信息，因此没有办法直接定位，但我们可以通过其它方式来排查；这里需要我们了解以下几个知识点(在问题排查中，有些知识点也是有些模糊，后面会通过实验进行验证)：
慢日志的Rows_examined：执行该SQL，实际扫描的行数，真实值
慢日志的Rows_sent：执行该SQL，实际返回的行数，对于update来说是0
慢日志记录的SQL：既包括符合条件的执行成功的SQL，也包括符合条件的执行失败的SQL，这里执行失败可能是手动rollback回滚或异常中断回滚
（5）第一次怀疑，异常时间点，可能走的是全表扫描，但对比表记录数和Rows_examined，相差一个数量级(亿级和千万级)，因此暂时排除这个可能性
（6）第二次怀疑，异常时间点，可能走的是其他索引扫描，但检查表结构未发现可用索引，而且ignore index idx_order_no_status查看执行计划也未发现有其他索引可用，因此也排查这个可能性
（7）第三次怀疑，异常时间点，可能走的就是idx_order_no_status这个索引，但该索引区分度不高，但检查发现order_no这个字段是订单号，区分度是非常高的，因此也排除这个可能性
（8）一时间没有头绪，只能先解析一下binlog，排查下是否存在与慢SQL相关信息；非常意外的是，在异常时间点的binlog日志中，没有发现该order_no对应的修改记录，这可以说明该SQL是没有成功执行的；排查到这里，问题就清晰了，随后找客户确认应用超时时间设置是30s，整个事情也就可以串起来了
（9）接下来简单总结一下，当时UPDATE xxx_order set status = 6 where order_no = 'xxx'这条SQL语句，因为某些原因，没有走idx_order_no_status索引，而是走的全表扫描，该表非常大，扫描到1400w行记录左右，超过30s应用超时断开，SQL被回滚，因此binlog没有记录，慢日志记录的Rows_examined只有1400万，而不是2亿；至于为什么SQL走的执行计划不对，因为没有现场暂时无法定位，但执行计划突变，一般是因为统计信息不准确或MySQL bug导致。
场景模拟
刚刚有提到几个知识点，其实在排查过程中也是有一些模糊，接下来我们通过实验验证下
（1）慢日志的Rows_examined：执行该SQL，实际扫描的行数，真实值
（2）慢日志的Rows_sent：执行该SQL，实际返回的行数，对于update来说是0
（3）慢日志记录的SQL：既包括符合条件的执行成功的SQL，也包括符合条件的执行失败的SQL，这里执行失败可能是手动rollback回滚或异常中断回滚
慢日志的Rows_examined
（1）sbtest9记录数为1000000，更新所有行记录，Rows_examined为1000000
# Time: 2021-02-24T09:37:49.542262+08:00
# User@Host: root[root] @ localhost [] Id: 33
# Query_time: 37.736135 Lock_time: 0.000089 Rows_sent: 0 Rows_examined: 1000000
SET timestamp=1614130669;
update sbtest9 set k=1000;（2）删掉一行记录，sbtest9记录数999999，再次更新所有行记录，Rows_examined为999999
# Time: 2021-02-24T10:01:51.101630+08:00
# User@Host: root[root] @ localhost [] Id: 33
# Query_time: 12.015041 Lock_time: 0.000091 Rows_sent: 0 Rows_examined: 999999
SET timestamp=1614132111;
update sbtest9 set k=100;可以多测试几次，结果都是一样的，Rows_examined记录的是真实值，而不是预估值
慢日志的Rows_sent
（1）对于insert/update/delete语句，Rows_sent返回均为0
# Time: 2021-03-01T11:48:42.002676+08:00
# User@Host: root[root] @ localhost [] Id: 36
# Query_time: 27.349989 Lock_time: 0.000113 Rows_sent: 0 Rows_examined: 1000000
SET timestamp=1614570522;
insert into sbtest9 select * from sbtest1;
# Time: 2021-03-01T12:58:28.822481+08:00
# User@Host: root[root] @ localhost [] Id: 37
# Query_time: 24.670155 Lock_time: 0.000108 Rows_sent: 0 Rows_examined: 1000000
SET timestamp=1614574708;
update sbtest9 set k=1000;
# Time: 2021-03-01T12:58:55.412557+08:00
# User@Host: root[root] @ localhost [] Id: 37
# Query_time: 12.941791 Lock_time: 12.889409 Rows_sent: 0 Rows_examined: 1000000
SET timestamp=1614574735;
delete from sbtest9;（2）对于select语句，Rows_sent返回为实际记录数
# Time: 2021-03-01T11:49:35.967156+08:00
# User@Host: root[root] @ localhost [] Id: 36
# Query_time: 0.357678 Lock_time: 0.000102 Rows_sent: 1 Rows_examined: 1000000
SET timestamp=1614570575;
select * from sbtest1 where pad='63188288836-92351140030-06390587585-66802097351-49282961843';慢日志记录的SQL
（1）手动rollback回滚的SQL，在语句执行完之后，就被记录在慢日志中；后续rollback并不会影响它，且rollback这个语句本身并不会记录在慢日志中
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into sbtest9 select * from sbtest1;
Query OK, 1000000 rows affected (24.58 sec)
Records: 1000000 Duplicates: 0 Warnings: 0
# Time: 2021-03-01T13:05:09.289912+08:00
# User@Host: root[root] @ localhost [] Id: 37
# Query_time: 24.584236 Lock_time: 0.000105 Rows_sent: 0 Rows_examined: 1000000
SET timestamp=1614575109;
insert into sbtest9 select * from sbtest1;
mysql> rollback;
Query OK, 0 rows affected (22.48 sec)（2）异常中断回滚的SQL，会被记录在慢日志中，且Rows_examined返回为中断时已经扫描的实际记录数
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into sbtest9 select * from sbtest1;
^C^C -- query aborted
ERROR 1317 (70100): Query execution was interrupted
# Time: 2021-03-01T13:09:24.816701+08:00
# User@Host: root[root] @ localhost [] Id: 37
# Query_time: 15.766142 Lock_time: 0.000098 Rows_sent: 0 Rows_examined: 368870
SET timestamp=1614575364;
insert into sbtest9 select * from sbtest1;总结
关于慢查询问题，总结如下：
在异常时间点，UPDATE xxx_order set status = 6 where order_no = 'xxx'这条SQL语句，因为某些原因，没有走idx_order_no_status索引，而是走的全表扫描，该表非常大，扫描到1400w行记录左右，超过30s应用超时断开，SQL被回滚，因此binlog没有记录，慢日志记录的Rows_examined只有1400万，而不是2亿；至于为什么SQL走的执行计划不对，因为没有现场暂时无法定位，但执行计划突变，一般是因为统计信息不准确或MySQL bug导致。
关于涉及的知识点，总结如下：
（1）慢日志的Rows_examined：执行该SQL，实际扫描的行数，真实值；
（2）慢日志的Rows_sent：执行该SQL，实际返回的行数，真实值；对于insert/update/delete语句而言，Rows_sent返回为0；对于select语句而言，Rows_sent返回为实际记录数；
（3）慢日志记录的SQL：既包括符合条件的执行成功的SQL，也包括符合条件的执行失败的SQL，这里执行失败可能是手动rollback回滚或异常中断回滚。
原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。
如有侵权，请联系 cloudcommunity@tencent.com 删除。
原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。
如有侵权，请联系 cloudcommunity@tencent.com 删除。