这一周线上碰到一个诡异的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。

在我忽然要放弃的时候，我忽然发现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，你还想当然的代入去查找问题，这当然会加大排查问题的难度。