现象

最近刚接手的一个项目,在某天中午12点30多分接到开发反馈,他们业务请求数据库的时候,出现了大量请求超时问题,虽然之前也有过,但是这次持续很久,大概两分钟多又恢复好了。
数据库版本8.0.22。隔离级别RR。

初步分析

接到问题,不着急,先看一下监控:

sql server 获取超时的语句 sql查询超时_SQL


sql server 获取超时的语句 sql查询超时_sql_02


从监控图上看可以看到在对应的12点36分左右的时候出现了连接数开始飙高,以及这个点出现了少量的慢sql.

查看的对应时间点的慢查询日志,查到对应时刻有如下的慢查询sql:

sql server 获取超时的语句 sql查询超时_big data_03


这里可以看到这个慢查询从12点36分执行了155s。

这个SQL按理说不会慢,因为(uid,msg_id)是一个uk索引,id是主键。

然后因为出现超时,所以猜测是因为锁导致的超时原因吗?

但是由于新项目没有很深层的关于锁相关监控,只能去查询存储引擎信息

Show engine innodb status\G; 这个只能看到最近一次的死锁信息。要想看到完整的死锁信息 建议打开innodb_print_all_deadlocks,该参数会将所有的死锁信息输出到 MySQL的error log当中。这样就不会错过对应时间点的死锁日志。 结果在里面发生了一条在对应时间点的死锁信息,如下:

sql server 获取超时的语句 sql查询超时_SQL_04

从最近一次的死锁日志里面,我们可以得知:

当时的时候出现了锁等待情况 这里需要声明一下锁等待和死锁的区别

1.死锁发生的时候会立即报错,并且回滚代价小的SQL。 锁等待是根据innodb_lock_wait_timeout 默认50s,如果在50s拿不到对应的锁,就会报错事务try again。 所以说死锁肯定是因为先出现锁等待的情况。

sql server 获取超时的语句 sql查询超时_sql server 获取超时的语句_05

  1. 当时的锁竞争主要在于主键索引上的record锁竞争导致 但是,从两个SQL来看,这两个SQL都是有uk索引的,最后主键不可能出现锁竞争的情况。

查到这里,有点没想法了,后面就想着只能回过头去看看执行计划了,是不是执行计划没有走到;

sql server 获取超时的语句 sql查询超时_SQL_06

神奇一幕发生了,这个SQL居然走了主键索引,那这就有思路了。
表里面的数据本来就2500w条,这里看到基本上像是扫描了全表,
如果是全表扫的话,对主键上全部加了锁,那这样就说的通了。

总结

问题的流程大概如下:
12点36分,这个慢SQL由于走错索引,拿了全部主键索引的gap和record锁
接着其他请求过来,因为innodb_lock_wait_timeout=50s的默认值情况下,
所以后续的SQL在拿不到锁等待50s之后报错try again,业务反应为超时。
就这样一直在这个慢查询执行期间,后边相应的SQL都没法拿到锁,都在50s后超时,
也因为等待,所以连接堆积,飙高,后边慢SQL 155s执行完毕,恢复正常。