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

[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 时间差这么多？然后加了行日志系统又自动恢复了？诡异，太诡异了，说没有鬼我是不信的

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

贴一个监控调用的数据，信息尽量都脱敏了，这是 C 服务 buildUserCacheData 的监控，时间都超过 20 秒了
[img][/img]

[huangmingyou]

skywalking 这样的 apm 软件有吗，或者阿里云自己的 apm ; 微服务调用链很复杂的，需要这些工具。

[villivateur]

你这还不算奇怪的，我甚至遇到过加一行注释，问题就突然消失了的

[teliang]

@huangmingyou 没有这些工具。。。

[chendy]

看看 mysql 慢查，看看有没有相关的查询（可能没有）
可能是应用和数据库之间的网络出了什么问题
或者应用的连接池配置有问题
或者是有其他的慢查询拖住了连接池导致后续请求要排队
可能的点很多很多，慢慢查吧。。。

[kaiger]

@villivateur 这就离谱。。。

[soupu626]

服务 sql 慢，本地查着快
怀疑有其他的慢 sql 把服务的数据库链接池打满了？
导致你这个简单 sql 拿不到链接，大量耗时其实是在等待链接，执行时间其实很快和你的本地连上去查是一样的

[akira]

和这行代码有关的可能性几乎是 0
现在移除掉这行代码 估计也是正常的

[zoharSoul]

应该是连接池被某个 sql 占满了.
导致正常 sql 也要 2000+ms 才拿到连接并执行, 但是执行是很快的.
你本地 nativecat 快也是因为这个,

[HiShan]

蹲一个后续 ）

[defunct9]

开 ssh，让我上去看看

[huangmingyou]

看 mysql slow log; 把怀疑的微服务停掉

[gBurnX]

当复杂系统，不容易及时排查出问题时，其实可以留一手：粗暴的监控大法：

1.能输出日志的 app，全部监控起来。

2.把你们自己写的程序里，每个函数、接口与数据库 rpc 、List/Queue/Cache 等 size，全部监控起来。

3.把 OS 、nginx 、iis 、db 等各种队列 /缓存 /容器 size，全部监控起来。

然后当 size 接近 total lenth 的 80%，以及 rpc 时间超过 3s 时，在监控面板报警。

性能问题，基本上就是这些，监控好了，就不会出现诡异问题了。

[opengps]

只看表象可以先推测一个可能的原因：直接清空缓存导致的缓存逻辑缺陷。
然后导致访问穿透缓存直达数据库，延伸到数据库压力过大，这个推测符合你说的单条查询也慢，至于重新发包回复，则往往是中断了慢查询占用的连接数等因素可能性比较大

[opengps]

简单来说，排查一下那些缓存时更新当晚没有及时回填的，可能会找到问题根源

[teliang]

@chendy
@soupu626
@zoharSoul
@opengps
@gBurnX
贴了个图，同一个 service 方法多次查询数据库不用每次都从连接池拿吧，应该是复用的才对呀

[zoharSoul]

@teliang #15 这要看是不是在一个事务里

[Digitalzz]

有没有用 Arthas 查看进入 Mapper 里的具体方法，这里面应该就可以看到是否是获取连接等到太长等问题。

或者说你们的 RDS 上是否可以看到当天连接数量的使用趋势图。

[cxh116]

看 web server 的线程数是不是大于数据库连接池的数量?
比如 web server 平常响应很快, 数据库连接很快释放回池.
但因某个查询慢,导致连接释放慢, 在数据连接不够时,其它 web 线程就要等池的连接释放才能够查询. 这就解释为什么 web server 查询慢,但 nativecat 查询快.
只是一种可能,对 java 相关的不太熟悉,供参考.

[opengps]

@teliang 是不是同一个查询链接跟是否同一个方法没有直接关系。这得看数据库访问层面是否同一个数据库查询实例之类的。虽然现在已经恢复了，不过你应该依然可以从 rds 后台查询到故障时段的 iops 指标，硬盘读写指标

[liyunyang]

"贴一个监控调用的数据，信息尽量都脱敏了，这是 C 服务 buildUserCacheData 的监控，时间都超过 20 秒了"

问一下楼主这个监控使用什么做的，准备给公司设计一个微服务的监控方案

[twl007]

当年阿里云遇到过一个类似的事情 也是数据库没有报警 但是速度变得非常慢 导致我们的 redis 里面大量的数据没有写回到 rds

开工单给阿里云 答复说那台 rds 的硬盘出现了问题 已经帮忙做了主从切换 遂解决 😑

[teliang]

@liyunyang 阿里的 Arthas

[teliang]

@zoharSoul #16 窝草，我看了一下，方法没有加事务注解

[cking]

我们也遇见过打死整个服务的 具体后面来查的时候 就是因为 tomcat 里面的线程(还是其他啥的) 有 200 个请求等待,导致后续的请求进来了之后就开始排队. 实际上 sql 并不慢 是 tomcat 里面的请求线程满了 你增加了日志以后 打包发版本 相当于就是重启了 tomcat 所以就会释放掉当时请求进来的一些 我们当时是 修改了 tomcat 的最大线程是 800(默认是 200) 后续就再也没有出现过这个问题了

[fkdtz]

用的量子计算机？当你试图监控它时，它就表现出相反的结果。

感觉不是这行代码的事儿，当时 DB 的资源占用怎么样？或者连接池被耗尽？猜测耗时大部分是在等待资源。

代码还原到当时的版本，在模拟环境搞个压测看看能否复现？

[Lemeng]

@villivateur 真有这种事，离奇

[snownarrow]

@defunct9 “开 ssh，让我上去看看” 发现这都快成为你的口头禅了

[zhoudaiyu]

@defunct9 哪都能看到你🐶

[defunct9]

@zhoudaiyu @snownarrow 是我，是我，还是我

[SilenceLL]

我们碰到过引用的 mysql 连接池满了， 重启服务以后就好了，，可能应用配置的连接池满了，拿不到连接了，但是 navicat 连接不走应用连接池所以没问题？

[redford42]

只有做好监控日志静待复现了

[proxychains]

@villivateur 离谱

[Smallsun1231]

@defunct9 #10 虽迟但到

[patx]

很多情况下，sql 执行慢不是 sql 有问题，可能是连接池满了，获取新的连接会等待空闲连接。如果一直拿不到，会等到超时。

[lizuoqiang]

有没有想过是 K8S 某个 Node 出问题了。

[kindjeff]

MySQL 监控没问题么

[popop1]

曾经双 11，阿里聚石塔部分硬盘出现过问题.切换后遂解决

[peanutcheeseball]

蹲个后续

[zhuweiyou]

@villivateur 一样遇到过, 然后把注释删了 也正常了.

[lei2j]

@defunct9 我就服你

[akira]

@kindjeff 用 ui 工具直连 mysql 并且执行正常的话，这种情况下 mysql 就是正常的

[ForkNMB]

数据库连接池没有监控吗 CAT 之类的上报有没有

[justNoBody]

所以是不是 13 楼说的那个可能性？

[bk201]

感觉像是阿里云内部网关问题

[Orlion]

Navicat 和微服务查询同一条 SQL 时间差这么多 可能是有慢查询导致连接池满了，请求线程都在等连接。

还是上监控吧😄

[snail00]

可能是服务的连接数限制比较小, 清了缓存后, 大量的查询挤占有限的连接数. 大家都在排队等链接.
这个限制保护了 RDS, 应该也不会体现在 RDS 监控中.
新起的服务没有历史包袱就恢复正常了.

[fengfisher3]

找阿里云问了吗？不太懂什么原因，也蹲个后续。

[Variazioni]

建议找个大师给服务器开开光。。

[v2hh]

是不是数据库连接池的问题，可以看下 wait 线程的堆栈信息

[railgun]

有没有可能之前跑的根本就不是最新代码，所以其实不只是加了一行日志这么简单？

[vindurriel]

我猜清空缓存之后问题就会复现 可能是哪个环节有锁 可以找个离线环境压测一下数据库

[HunterPan]

慢的话 查看线程栈 一目了然，

[chenshun00]

当时的堆栈有没有，目标服务的堆栈，10s 超时，肯定有一些地方阻塞了。顺着链路找应该有下文吧

[palfortime]

应该是代码的问题，某种特定情况触发的吧。132 是 service 不是 mapper 也耗时超过两秒（ 132 那个函数是不是进入会开事务？）。138 那里，一个 service 构造要 10ms 也有点奇怪（有申请什么资源？）。不是启动就应该注入完了？还要动态生成 service ？

[podel]

阿里云 rds 有慢日志和 sql 审计功能 都可以开起来看看。

[rekulas]

慢的时候，重点检查有没有太多执行中事务，如果没有就考虑连接数不够的问题

[JamChiu]

给阿里提个工单压压惊

[hujun528]

有点像 数据库 产生 死锁，死锁解除后 查询会恢复正常

[pjntt]

“发现主要业务流量入口 M 服务调用 Cache 服务一直超时，调用 C 主要是 M 从 Redis 获取不到用户缓存，需要 C 构建缓存放 Redis 。”
这个明显是缓存击穿了，访问压力直接堆到数据库里。

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

‘“构建缓存”这里用到事务了吗？如果有事务，那感觉是这个事务执行时间长，导致链接池占满了。

[xupefei]

提醒一下，在有些公司安全部门点头以前都不算脱敏…

[towry]

阿里云的锅

[raptor]

有一定概率是阿里云的锅

[Xavi1996]

插眼看最后定论

[jorneyr]

K8S 的网络很魔幻的，我遇到过从 Pod 内部访问其他 Pod 很慢，从宿主机访问其他 Pod 就正常，而且不是一直这样。

[buster]

有个疑问的地方前面有兄弟说是服务连接池被占了，加了日志重新发布链接清掉了，但是前面也重启过啊，感觉对不上。

[bsg1992]

不可能是连接池满导致查询满 服务器都重启了。正常来说连接肯定都是释放的。我怀疑是内部网络问题

[pkoukk]

瞎猜有一定概率是 K8s 某个 node 到 db 有问题，重启，调度还在这个 node 上
改代码之后是重新部署，调度到了别的 node 上，然后就正常了

[X0ray]

有没有看过 redis 连接数，redis 连接泄露的问题需要关注下。

[luwill]

大概率 mysql 连接池满了，重启连接池清空了。应该还会复发，看出问题前的请求日志，当天的 mysql 慢日志。

[securityCoding]

1. 调用 cache 为什么会超时呢?是不是 redis 没连接了

[securityCoding]

@luwill 应该不是,看问题描述先从缓存取数据失败(超时)导致大量请求直接查 db 导致 db 压力过大.直接原因大概率是 redis 获取不到连接

[u011631336]

大概率是跟数据库有关系，存在锁、事务的原因比较大

[joApioVVx4M4X6Rf]

求结果

[repus911]

有没有可能是应用数据库链接池设置的比较小

[wineast]

大概率是因为重新部署起了作用，而不是那一行代码，至于重新部署部署导致了 node 节点的重新分配还是数据库连接的重新连接，不确定

[3kkkk]

通过 actuator 看下每个服务线程占用情况。应该是哪里阻塞了。

[qq1340691923]

我也想说连接池打满了，可作者他们试过了重启啊

[superliuliuliu1]

是小鹅通吗？听说昨天下午小鹅通崩了

[PDX]

如果重新构建缓存，很可能打满连接池，这种情况很常见。

[aoxiansheng]

数据库也是买的阿里的 RDS 。原来我们的业务用 RDS 就卡死。用自建就正常。

[huxiweng]

先看看你的 ECS 请求 RDS 有没有超时！
我前段时间被腾讯坑了，原因是 DNS 解析域名失败，赔了我 1500 块云服务器余额。