记录一个诡异的线上宕机事故,大佬们帮忙排查一下问题呀

2021-09-09 11:48:14 +08:00
 teliang

环境

二三十个微服务 SpringBoot+Dubbo 部署在阿里的 K8S 上,数据库也是买的阿里的 RDS,听领导说配置还挺高的,支持主备自动切换什么的。

事故起因和经过

大版本上线,改了用户的缓存数据结构,凌晨上线时把 Redis 用户缓存全清了,上线当晚验证功能正常,白天运行也十分稳定。

下午 5 点多业务高峰的时候运营反馈系统蹦了,看后台是数据库负载正常、Dubbo 调用全部超时,领导首先怀疑是系统被攻击了,然后在阿里的后台打开了防火墙增强模式(具体叫什么不懂,效果是可以阻拦大部分到 Nginx 的请求),开完观察了好久后台调用还是超时,老板都开始炸锅了跑来了解情况,领导开始尝试万能的重启大法,ZK 的三个节点都重启了,微服务也挨个重启,绝望的是重启依然没有任何效果。

一顿瞎搞时间很快就到了晚上 8 点,这时候已经宕机 2 个多小时了还没找到原因,也不知道怎么恢复。然后我试着用 Arthas 监控了一下调用时间,发现主要业务流量入口 M 服务调用 Cache 服务一直超时,调用 C 主要是 M 从 Redis 获取不到用户缓存,需要 C 构建缓存放 Redis 。监控 C 服务的时候发现所有请求数据库的耗时都要 2000ms 以上,然后我们构建缓存需要读 8~9 次数据库但是 Dubbo 的超时时间设的是 10s 所以一直超时。

诡异事件

首先怀疑是 SQL 写的有问题,但是有一个根据主键 ID 查询单表的居然也要 2000+ms,这就非常离谱了,后面我把参数打出来自己拼接 SQL 用 Navicat 查询只要十几毫秒,领导说可能是工具监控有问题,然后当场给这个查询加调用时间的日志验证,从 master 拉的分支,只加了一行日志!!!

然后,重新发包观察,诡异的是,系统恢复正常了!!!没有调用超时的日志,新加的那行日志打印出来的也是十几毫秒,其他服务也能正常调用了!!!

事故报告

领导给的事故报告是晚上清除用户缓存,没有预先跑脚本构建缓存导致业务高峰期系统宕机。

疑惑

为什么那个时间点 Navicat 和微服务查询同一条 SQL 时间差这么多?然后加了行日志系统又自动恢复了?诡异,太诡异了,说没有鬼我是不信的

大佬们来帮忙排查一下这可能是什么原因呀

10418 次点击
所在节点    Java
81 条回复
akira
2021-09-09 17:51:58 +08:00
@kindjeff 用 ui 工具直连 mysql 并且执行正常的话,这种情况下 mysql 就是正常的
ForkNMB
2021-09-09 18:22:31 +08:00
数据库连接池没有监控吗 CAT 之类的上报有没有
justNoBody
2021-09-09 18:29:58 +08:00
所以是不是 13 楼说的那个可能性?
bk201
2021-09-09 18:30:40 +08:00
感觉像是阿里云内部网关问题
Orlion
2021-09-09 18:39:13 +08:00
Navicat 和微服务查询同一条 SQL 时间差这么多 可能是有慢查询导致连接池满了,请求线程都在等连接。

还是上监控吧😄
snail00
2021-09-09 18:56:22 +08:00
可能是服务的连接数限制比较小, 清了缓存后, 大量的查询挤占有限的连接数. 大家都在排队等链接.
这个限制保护了 RDS, 应该也不会体现在 RDS 监控中.
新起的服务没有历史包袱就恢复正常了.
fengfisher3
2021-09-09 19:02:24 +08:00
找阿里云问了吗?不太懂什么原因,也蹲个后续。
Variazioni
2021-09-09 19:50:29 +08:00
建议找个大师给服务器开开光。。
v2hh
2021-09-09 20:10:17 +08:00
是不是数据库连接池的问题,可以看下 wait 线程的堆栈信息
railgun
2021-09-09 20:23:22 +08:00
有没有可能之前跑的根本就不是最新代码,所以其实不只是加了一行日志这么简单?
vindurriel
2021-09-09 20:31:29 +08:00
我猜清空缓存之后问题就会复现 可能是哪个环节有锁 可以找个离线环境压测一下数据库
HunterPan
2021-09-09 20:57:07 +08:00
慢的话 查看线程栈 一目了然,
chenshun00
2021-09-09 21:05:43 +08:00
当时的堆栈有没有,目标服务的堆栈,10s 超时,肯定有一些地方阻塞了。顺着链路找应该有下文吧
palfortime
2021-09-09 21:14:57 +08:00
应该是代码的问题,某种特定情况触发的吧。132 是 service 不是 mapper 也耗时超过两秒( 132 那个函数是不是进入会开事务?)。138 那里,一个 service 构造要 10ms 也有点奇怪(有申请什么资源?)。不是启动就应该注入完了?还要动态生成 service ?
podel
2021-09-09 21:16:25 +08:00
阿里云 rds 有慢日志和 sql 审计功能 都可以开起来看看。
rekulas
2021-09-09 21:32:58 +08:00
慢的时候,重点检查有没有太多执行中事务,如果没有就考虑连接数不够的问题
JamChiu
2021-09-09 21:48:19 +08:00
给阿里提个工单压压惊
hujun528
2021-09-09 22:48:17 +08:00
有点像 数据库 产生 死锁,死锁解除后 查询会恢复正常
pjntt
2021-09-09 22:55:55 +08:00
“发现主要业务流量入口 M 服务调用 Cache 服务一直超时,调用 C 主要是 M 从 Redis 获取不到用户缓存,需要 C 构建缓存放 Redis 。”
这个明显是缓存击穿了,访问压力直接堆到数据库里。

“构建缓存需要读 8~9 次数据库但是 Dubbo 的超时时间设的是 10s 所以一直超时。”

‘“构建缓存”这里用到事务了吗?如果有事务,那感觉是这个事务执行时间长,导致链接池占满了。
xupefei
2021-09-10 00:49:20 +08:00
提醒一下,在有些公司安全部门点头以前都不算脱敏…

这是一个专为移动设备优化的页面(即为了让你能够在 Google 搜索结果里秒开这个页面),如果你希望参与 V2EX 社区的讨论,你可以继续到 V2EX 上打开本讨论主题的完整版本。

https://www.v2ex.com/t/800791

V2EX 是创意工作者们的社区,是一个分享自己正在做的有趣事物、交流想法,可以遇见新朋友甚至新机会的地方。

V2EX is a community of developers, designers and creative people.

© 2021 V2EX