一个诡异的MySQL查询超时问题,居然隐藏着存在了两年的BUG (2)

在我突然要放弃的时候,我突然发现SQL日志记录里面的时区都是标准时区的,而我那个任务执行的时候是北京时间,要知道标准时区和北京时区是差了8个小时的!

image-20210418171840432

好家伙!我都要想到量子力学了,结果发现时区没对上?

会不会是DBA找慢SQL的时候时间找错了啊?

我将这个“重大发现”告诉了DBA,DBA帮我重新跑一份慢SQL,好家伙,出现了我想要那个表的慢SQL。

image-20210418155058957

从日志上面可以看到,查询的日期区间从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,你还想当然的代入去查找问题,这当然会加大排查问题的难度。

内容版权声明:除非注明,否则皆为本站原创文章。

转载注明出处:https://www.heiqu.com/wsffjp.html