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

这一周线上碰到一个诡异的BUG。

线上有个定时任务,这个任务需要查询一个表几天范围内的一些数据做一些处理,每隔十分钟执行一次,直至成功。

通过日志发现,从凌晨5:26分开始到5:56任务执行了三次,三次都因为SQL查询超时而执行失败,而诡异的是,任务到凌晨6:00多就执行成功了。

每天都是凌晨五点多失败,凌晨六点执行成功。

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

点开异常日志一看是这样的:

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

总结来说就是MySQL查询超时。

像这种稳定复现的BUG,我原以为只需三分钟能定位,没有想到却耗费了我半天的时间。

排查之路

Explain

看到超时SQL,大多数人第一反应就是这个SQL没有走索引,我也不例外,我当时的第一反应就是这条SQL没有走索引。于是,我将日志里面的SQL复制了出来,脱敏处理一下大概是这样的一条SQL:

select * from table_a where status_updated_at >= ? and status_updated_at < ?

SQL里面有两个日期参数,这两个起始日期是某种商品的可交易时间区间,相隔三到五天,我取了17天的时间间隔的保守值,Explain了一下这条SQL。

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

从图上可以看到这条SQL的执行还是走了索引的。走的是根据status_updated_at字段建立的索引。

执行了一下也只耗时了135毫秒。

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

根据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个小时的!

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

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

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

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

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

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

Original: https://www.cnblogs.com/coderw/p/14676343.html
Author: CoderW喜欢写博客
Title: 一个诡异的MySQL查询超时问题,居然隐藏着存在了两年的BUG

原创文章受到原创版权保护。转载请注明出处:https://www.johngo689.com/715269/

转载文章受原作者版权保护。转载请注明原作者出处!

(0)

大家都在看

  • Qt 保持窗口顶层显示最简单方法

    情景: 当前存在两个窗口或以上,先初始化的窗口会被后初始化的窗口覆盖,从而置于底层, 这时一个最简单的方案就是给需要置于顶层的窗口配置事件过滤器,监听窗口状态,当窗口不属于顶层窗口…

    技术杂谈 2023年7月11日
    086
  • HIT软构博客2-java异常和final语法

    final的用法: 修饰变量:final关键字修饰的基本数据类型变量称为常量,不可更改。 final修饰的引用类型是不能改变其引用地址的,但可以改变地址内部属性。 修饰方法:fin…

    技术杂谈 2023年7月11日
    0112
  • css中子元素设置margin-top为什么影响了父元素

    本文介绍了css中子元素设置margin-top为什么影响了父元素,分享给大家,具体如下: 1 2 class="show"> crystal 两个div…

    技术杂谈 2023年5月31日
    0137
  • C 中的字符数组

    在C语言中没有专门的字符串变量,字符串实际上是使用 null 字符 \0 终止的一维字符数组。因此,一个以 null 结尾的字符串,包含了组成字符串的字符。通常用一个 字符数组来存…

    技术杂谈 2023年7月10日
    0121
  • copy与mutableCopy区别,strong和copy的使用

    本篇文章主要讲两个知识点:1.深拷贝与浅拷贝 2.NSArray和NSMutaleArray应该用copy还是stong修饰。 一、我们先来分析深拷贝(返回一个对象,一个新的指针指…

    技术杂谈 2023年5月30日
    0110
  • coroot-pg-agent 专注性能的pg promtheus exporter

    尽管已经有不少pg 的prometheus exporter 了,但是coroot-pg-agent 是关注与查询性能统计的还是很支持使用的pmm 也是支持pg 的,同时基于pro…

    技术杂谈 2023年5月30日
    0116
  • shopify主题Pacific模板配置修改

    Shopify Pacific主题一个经受住了时间考验的经典 Shopify 主题,与现有的OS 2.0兼容。使用经过验证的灵活主题建立您的业务,以帮助商店发展。非常适合 五金与汽…

    技术杂谈 2023年5月31日
    0173
  • 百钱买百鸡问题

    百钱买百鸡问题 题目:公元前5世纪末,中国古代数学家张丘建在他的《算经》中提出了著名的 “百钱买百鸡问题”:鸡翁一,值钱五,鸡母一,值钱三,鸡雏三,值钱一,…

    技术杂谈 2023年7月11日
    0111
  • html大文件分段传输

    总结一下大文件分片上传和断点续传的问题。因为文件过大(比如1G以上),必须要考虑上传过程网络中断的情况。http的网络请求中本身就已经具备了分片上传功能,当传输的文件比较大时,ht…

    技术杂谈 2023年5月30日
    0129
  • kube-scheduler的调度上下文

    404. 抱歉,您访问的资源不存在。 可能是网址有误,或者对应的内容被删除,或者处于私有状态。 代码改变世界,联系邮箱 contact@cnblogs.com 园子的商业化努力-困…

    技术杂谈 2023年7月24日
    0107
  • 强大的DOM变化观察者MutationObserver

    可以监听到属性、文本内容、节点插入删除、子节点变化等事件。可是该事件 W3C 已废弃,虽然一些浏览器仍然支持,但不建议使用。 MutationObserver目前IE11+及其它浏…

    技术杂谈 2023年6月1日
    0103
  • 判断 iframe 是否加载完成的完美方法

    一般来说,我们判断 iframe 是否加载完成其实与 判断 JavaScript 文件是否加载完成 采用的方法很类似:var iframe = document.createEle…

    技术杂谈 2023年6月1日
    0152
  • Python——静态方法、类方法、公有方法、私有方法

    普通实例方法,第一个参数需要是self,它表示一个具体的实例本身。 静态方法是类中不需要实例的函数,无self,仅仅是类中的函数。可以由类实例或类调用。(1)使用staticmet…

    技术杂谈 2023年7月11日
    0101
  • FlinkSql之TableAPI详解

    Flink 的 Table API和 SQL是流批统一的 API。 这意味着 Table API & SQL 在无论有限的批式输入还是无限的流式输入下,都具有相同的语义。 …

    技术杂谈 2023年7月24日
    0124
  • python安装各种库的镜像

    让python pip使用国内镜像#国内源:#清华:https://pypi.tuna.tsinghua.edu.cn/simple 阿里云:https://mirrors.ali…

    技术杂谈 2023年7月24日
    094
  • 存储学习

    在本站不再更新,在CSDN上继续更新:https://blog.csdn.net/pengdonglin137/article/details/130813687 Linux I/…

    技术杂谈 2023年5月31日
    0164
亲爱的 Coder【最近整理,可免费获取】👉 最新必读书单  | 👏 面试题下载  | 🌎 免费的AI知识星球