线上有个定时任务,这个任务须要查询一个表几天范围内的一些数据做一些处理,每隔十分钟实行一次,直至成功。
通过日志创造,从凌晨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。
在我溘然要放弃的时候,我溘然创造SQL日志记录里面的时区都是标准时区的,而我那个任务实行的时候是北京韶光,要知道标准时区和北京时区是差了8个小时的!
好家伙!
我都要想到量子力学了,结果创造时区没对上?
会不会是DBA找慢SQL的时候韶光找错了啊?
我将这个“重大创造”见告了DBA,DBA帮我重新跑一份慢SQL,好家伙,涌现了我想要那个表的慢SQL。
从日志上面可以看到,查询的日期区间从2020年9月到2021年4月,韶光跨度7个月。MySQL本钱打算的时候认为区间太大,走索引还不如直接扫描全表,终极没有走索引扫描了1800W条数据。
说好的韶光区间最多七天呢?怎么变成了七个月?
赶紧定位代码,定位创造底层在取韶光区间时,调了一个RPC接口,这个接口预期返回的韶光区间只有几天,结果返回了七个月的韶光区间。这段逻辑是18年上线的。
于是联系供应这个RPC接口的干系职员,通过查找验证确定这是底层数据的问题,该当返回几天结果返回了几个月。
末了修复了干系数据,增加了相应的校验和监控,重新发布系统,这个存在了两年的BUG也就得以办理了。
这个故事到这里也就结束了。
再回顾一下,还有几个问题须要回答一下:
不走索引,那为什么六点多实行就没有超时呢?缘故原由便是六点基本上没有业务在调用MySQL,那个时候的MySQL的资源是非常充足的,加上MySQL的机器也配置非常的高,以是这条SQL硬生生跑成功了。听起来有点离谱,但确实是这样的。
为什么这个BUG在线上这么久了,现在才创造?这个韶光区间底层数据用的不多,目前只创造只有这个超时SQL任务在调用。
原来业务量没有这么大,加上机器配置高,扫描全体表也花不了多久韶光。凌晨五六点实行,没有对线上的做事造成影响。
任务失落败是很正常的,由于还依赖一些其他数据,其他数据供应的韶光不愿定,以是任务会一贯跑直到成功。
总结复盘一下全体过程,对付这个查询超时SQL问题的排查,我从索引、网络、备份、业务竞争MySQL资源等方面逐一剖析,却忽略了最主要的成分——实行的到底是哪一条SQL。
我想当然的认为实行的SQL便是我想象中的那样并对此笃信不疑,后面的努力也就成了徒劳。
这本是一个大略的问题,我却把他繁芜化了,这是不应该的。
这是一个范例的例子,业务量不大的时候埋下的坑,业务发展迅速的时候就暴露了,万幸的是,没有影响到核心交易系统,如果是核心交易系统的话,可能就会导致一次P0的事件。
虽然这个代码不是我写的,但我从中得到的教训便是对线上环境要有敬畏之心,对依赖数据要有疑惑之心,对问题排查要有客不雅观之心。
线上的环境极其繁芜,有着各自版本迁移和业务变更遗留下来的数据,这些情形开拓职员是无法全部考虑到的,测试也很难覆盖测试,带着主不雅观的想法去写代码很随意马虎导致BUG,有些BUG在业务量还不大的时候不随意马虎引起重视,但随着业务的发展,这些欠下的债究竟要还。
你可以担保你写的逻辑没有问题,但是你不能担保做事上游供应的数据都符合预期。多想一下如果上游数据非常,自己写的做事会不会出问题,多加一些数据校验和报警会省去很多不必要的麻烦。
排查问题的时候,一定要客不雅观,不要带着主不雅观的感想熏染。本来便是由于主不雅观而导致的BUG,你还想当然的代入去查找问题,这当然会加大排查问题的难度。