这一周线上碰到一个诡异的 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，你还想当然的代入去查找问题，这当然会加大排查问题的难度。