一个诡异的MySQL慢日志问题
这是学习笔记的第 2186 篇文章
读完需要
2
分钟速读仅需1分钟
今天和同事处理了一个MySQL慢日志的问题,从这两天开始频繁收到一些报警信息,但是查看数据库端却没有任何异常。
经过了几轮排查,最后结果刷新我对于问题的理解。
从产生这些报警开始,报警就一直非常频繁,频繁到我想尽快解决这个问题。
最开始定位问题的方向是有一些业务的SQL没有使用索引,但是执行时间很短,可能导致被判别为慢查询,可以通过修改参数 log_queries_not_using_indexes 进行调整。
调整之后从慢日志来看,已经几乎没有慢日志了,但是从监控来看梳理依旧很大,是3万多个。
以下是打开和关闭log_queries_not_using_indexes前后,这个环境中的慢日志数量统计,就算按照已有的评判标准,慢日志个数最多也不会超过100个,但是报警却显示是3万多个。
查看全局变量slow_queries的结果可以看到,这个环境中的全局变量值为30118
>show global status like '%slow%';
+---------------------+-------+
| Variable_name | Value |
+---------------------+-------+
| Slow_launch_threads | 0 |
| Slow_queries | 30118 |
+---------------------+-------+
2 rows in set (0.00 sec)
但是查看会话状态却发现这个值始终是0
>show status like '%slow%';
+---------------------+-------+
| Variable_name | Value |
+---------------------+-------+
| Slow_launch_threads | 0 |
| Slow_queries | 0 |
+---------------------+--
这个问题的瓶颈其实不在于show global status和 show status的差异,还是简单说下,show global status得到的是数据库启动以来的累计状态值,要得到某一个时间点的数据,那么就需要对上一次的状态进行对比,比如现在的全局状态是3000,而一个小时前是2000,那么在这一个小时内的增量就是1000,所以哪怕会话层存在局限性,但是show global status反复检查都是稳定不变,也足以说明这个问题的奇怪。
我甚至怀疑,是不是MySQL的一个bug导致了这种奇怪的抖动现象。
从这个业务来看,本身的访问频率其实是不高的,数据写入也不多。
所以排除了这个层面的原因之后,我开始关注于监控层面,我抓取了本机的监控层面的一些数据,发现监控层面是按照时间来提取数据,
类似:
时间1,slow_queries值 30000
时间2,slow_queries值 30000
从日志来看显然也是没有问题的,增量明显是0,就算有的话也应该是个位数的抖动,但是为什么监控系统会识别异常呢。
我们继续进行分析,突然同事提醒了一句说,是不是上传的数据IP存在异常,让我们恍然大悟,比如本机上传的监控数据是没错的,但是如果另外一个客户端也上传了监控数据,但是把客户端IP的信息写错了,在监控服务端是会收到两份上传的数据,就可能触发如下的逻辑:
时间1:服务器1,slow_queries值 30000
时间2:服务器2,slow_queries值 2
时间3:服务器1,slow_queries值 30000
时间4:服务器2,slow_queries值 1
这种情况下,在服务端来看就是慢日志的增量在30000->2->30000->1之间进行频繁的变换。
所以这个问题就充分说明尽管你已经做得很好了,但是还是可能有其他环节会严重影响到你,记的第 2186 篇文章
读完需要
2分钟
速读仅需1分钟
今天和同事处理了一个MySQL慢日志的问题,从这两天开始频繁收到一些报警信息,但是查看数据库端却没有任何异常。
经过了几轮排查,最后结果刷新我对于问题的理解。
从产生这些报警开始,报警就一直非常频繁,频繁到我想尽快解决这个问题。
最开始定位问题的方向是有一些业务的SQL没有使用索引,但是执行时间很短,可能导致被判别为慢查询,可以通过修改参数 log_queries_not_using_indexes 进行调整。
调整之后从慢日志来看,已经几乎没有慢日志了,但是从监控来看梳理依旧很大,是3万多个。
以下是打开和关闭log_queries_not_using_indexes前后,这个环境中的慢日志数量统计,就算按照已有的评判标准,慢日志个数最多也不会超过100个,但是报警却显示是3万多个。

查看全局变量slow_queries的结果可以看到,这个环境中的全局变量值为30118
>show global status like '%slow%';
+---------------------+-------+
| Variable_name | Value |
+---------------------+-------+
| Slow_launch_threads | 0 |
| Slow_queries | 30118 |
+---------------------+-------+
2 rows in set (0.00 sec)
但是查看会话状态却发现这个值始终是0
>show status like '%slow%';
+---------------------+-------+
| Variable_name | Value |
+---------------------+-------+
| Slow_launch_threads | 0 |
| Slow_queries | 0 |
+---------------------+--
这个问题的瓶颈其实不在于show global status和 show status的差异,还是简单说下,show global status得到的是数据库启动以来的累计状态值,要得到某一个时间点的数据,那么就需要对上一次的状态进行对比,比如现在的全局状态是3000,而一个小时前是2000,那么在这一个小时内的增量就是1000,所以哪怕会话层存在局限性,但是show global status反复检查都是稳定不变,也足以说明这个问题的奇怪。
我甚至怀疑,是不是MySQL的一个bug导致了这种奇怪的抖动现象。
从这个业务来看,本身的访问频率其实是不高的,数据写入也不多。
所以排除了这个层面的原因之后,我开始关注于监控层面,我抓取了本机的监控层面的一些数据,发现监控层面是按照时间来提取数据,
类似:
时间1,slow_queries值 30000
时间2,slow_queries值 30000
从日志来看显然也是没有问题的,增量明显是0,就算有的话也应该是个位数的抖动,但是为什么监控系统会识别异常呢。
我们继续进行分析,突然同事提醒了一句说,是不是上传的数据IP存在异常,让我们恍然大悟,比如本机上传的监控数据是没错的,但是如果另外一个客户端也上传了监控数据,但是把客户端IP的信息写错了,在监控服务端是会收到两份上传的数据,就可能触发如下的逻辑:
时间1:服务器1,slow_queries值 30000
时间2:服务器2,slow_queries值 2
时间3:服务器1,slow_queries值 30000
时间4:服务器2,slow_queries值 1
这种情况下,在服务端来看就是慢日志的增量在30000->2->30000->1之间进行频繁的变换。
所以这个问题就充分说明尽管你已经做zhen得很好了,但是还是可能有其他环节会严重影响到你,真可谓:人在公司忙,锅从天上来。
要修复这个问题,也相对比较简单,我提取了近几天的服务变更情况,就很快缩小了范围,很快定位到了这台服务器。
QQ群号:763628645
QQ群二维码如下, 添加请注明:姓名+地区+职位,否则不予通过
订阅我的微信公众号“杨建荣的学习笔记”,第一时间免费收到文章更新。别忘了加星标,以免错过新推送提示。
7
近期热文
你可能也会对以下话题感兴趣。点击链接就可以查看。
使用Python分析北京积分落户数据,分析完我陷入了深思
MySQL的主键命名挺任性,就这么定了
华裔教授发现二次方程极简解法,我默默的做了下验算
回答:我不小心把公司的数据库给删了,该不该离职?
迁移到MySQL的业务架构演进实战
数据库修改密码风险高,如何保证业务持续,这几种密码双活方案可以参考
MySQL业务双活的初步设计方案
如何优化MySQL千万级大表,我写了6000字的解读
一道经典的MySQL面试题,答案出现三次反转
业务双活的数据切换思路设计(下)
业务双活的数据切换思路设计(一)
MySQL中的主键和rowid,看似简单,其实有一些使用陷阱需要注意
小白学MySQL要多久?我整理了10多个问题的答案
8
转载热文
你可能也会对以下话题感兴趣,文章来源于转载,点击链接就可以查看。
去IOE or Not?
拉里·佩奇(Larry Page)的伟大归来
《吊打面试官》系列-Redis基础
唯一ID生成算法剖析,看看这篇就够了
关于大数据运维能力的一些思考
DBA菜鸟的进化简史:不忘初心,记工作中踩过的三个坑
美女主持直播,被突发意外打断!湾区网友却高喊: 我懂!超甜