这一周线上碰到一个诡异的BUG。
线上有个定时任务,这个任务需要查询一个表几天范围内的一些数据做一些处理,每隔十分钟执行一次,直至成功。
通过日志发现,从凌晨5:26分开始到5:56任务执行了三次,三次都因为SQL查询超时而执行失败,而诡异的是,任务到凌晨6:00多就执行成功了。
每天都是凌晨五点多失败,凌晨六点执行成功。
点开异常日志一看是这样的:
总结来说就是MySQL查询超时。
像这种稳定复现的BUG,我原以为只需三分钟能定位,没有想到却耗费了我半天的时间。
排查之路 Explain看到超时SQL,大多数人第一反应就是这个SQL没有走索引,我也不例外,我当时的第一反应就是这条SQL没有走索引。于是,我将日志里面的SQL复制了出来,脱敏处理一下大概是这样的一条SQL:
select * from table_a where status_updated_at >= ? and status_updated_at < ?SQL里面有两个日期参数,这两个起始日期是某种商品的可交易时间区间,相隔三到五天,我取了17天的时间间隔的保守值,Explain了一下这条SQL。
从图上可以看到这条SQL的执行还是走了索引的。走的是根据status_updated_at字段建立的索引。
执行了一下也只耗时了135毫秒。
根据Explain结果,我当时的推断是:这条SQL肯定走了索引,如果没有走索引,那六点多钟的查询肯定也会超时,因为这个表的数据是千万级别的。
为了验证这一推断,我找DBA帮我导出了一下凌晨5点到早上7点关于这个表的慢SQL,DBA告诉我那个时间段没有关于这个表的慢SQL。
这也进一步验证了我说推断:这条SQL走了索引,只是在五点多的时候因为一些神秘原因导致了超时。
接下来,需要做的就是找出这个神秘的原因。
按照以往的经验,我认为有这几点因素会导致查询超时
MySQL资源竞争
数据库备份
网络
MySQL资源竞争首先,我通过监控系统查看了那段时间MySQL的运行情况,连接数和CPU负载等指标都非常正常。所以,因为MySQL负载导致超时首先就可以被排除。
那会不会是其他业务操作这个表影响的呢?
首先,我们线上数据库事务隔离级别设置的是RR(可重复读),因为MVCC的存在,简单的修改肯定是不会影响查询至超时的。
要想影响唯一的可能性就是别的业务在update这个表数据的时候,更新条件没有走索引,导致行锁升级成表锁,并且,这个操作要刚好在凌晨5点多执行,且持续了半个小时。
这个条件非常苛刻,我检查了相关的代码,问了相关负责人,并没有这种情况,所有的更新都是根据Id主键更新的。关键是,如果更新SQL的更新条件没有走索引,肯定会是一个慢SQL的,那么,我们在慢SQL日志文件里面就能找到它,实际上并没有。
备份是不是因为凌晨5点多,数据库在备份的原因呢?
首先备份锁表不会锁这么久,这个任务是前前后后半个小时都执行失败了;
其次我们是备份的从库,并不是备份的主库;
最后,我们的备份任务都不是凌晨五点执行的。
所以,因为备份导致超时可以排除了。
网络是不是网络波动的原因呢?
我找运维同学帮忙看了一下执行任务的那台机器那段时间的网络情况,非常平缓没有丝毫问题,机房也没有出现什么网络抖动的情况。
再者,如果是网络问题,肯定会影响其他任务和业务的,事实上,从监控系统中查看其他业务并没有什么异常。
所以,因为网络波动导致超时也可以排除了。
转机我先后排除了索引、网络、备份、业务竞争MySQL资源等因素,在脑海里模拟了N种情况,脑补了一条SQL整个执行过程,想不到会有什么其他原因了。
这个事情变得诡异了起来,DBA劝我暂时放弃,建议我把任务执行时间延后,加一些监控日志再观察观察。毕竟,又不是不能用。
放弃是不可能放弃的,我是一个铁头娃,遇到BUG不解决睡不着觉。
理清思路,从头来过,我向DBA要了一份线上五点到六点的慢SQL的文件,自己重新找了一遍,还是没有找到这个表相关的慢SQL。