这是一个创建于 1205 天前的主题，其中的信息可能已经有所发展或是发生改变。
环境
二三十个微服务 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 时间差这么多？然后加了行日志系统又自动恢复了？诡异，太诡异了，说没有鬼我是不信的
大佬们来帮忙排查一下这可能是什么原因呀
第 1 条附言 · 2021-09-09 13:23:49 +08:00
贴一个监控调用的数据，信息尽量都脱敏了，这是 C 服务 buildUserCacheData 的监控，时间都超过 20 秒了
[img]
[/img]
[img]
[/img] |
1
huangmingyou 2021-09-09 11:51:15 +08:00
skywalking 这样的 apm 软件有吗，或者阿里云自己的 apm ; 微服务调用链很复杂的，需要这些工具。
|
 |
2
villivateur 2021-09-09 11:54:45 +08:00 via Android
你这还不算奇怪的，我甚至遇到过加一行注释，问题就突然消失了的
|
 |
3
teliang OP @huangmingyou 没有这些工具。。。
|
 |
4
chendy 2021-09-09 11:56:53 +08:00
看看 mysql 慢查，看看有没有相关的查询（可能没有）
可能是应用和数据库之间的网络出了什么问题 或者应用的连接池配置有问题 或者是有其他的慢查询拖住了连接池导致后续请求要排队 可能的点很多很多，慢慢查吧。。。 |
 |
5
kaiger 2021-09-09 11:58:03 +08:00
@villivateur 这就离谱。。。
|
 |
6
soupu626 2021-09-09 12:01:39 +08:00  3
服务 sql 慢，本地查着快
怀疑有其他的慢 sql 把服务的数据库链接池打满了？ 导致你这个简单 sql 拿不到链接，大量耗时其实是在等待链接，执行时间其实很快和你的本地连上去查是一样的 |
 |
7
akira 2021-09-09 12:02:13 +08:00 1
和这行代码有关的可能性几乎是 0
现在移除掉这行代码 估计也是正常的 |
 |
8
zoharSoul 2021-09-09 12:46:00 +08:00
应该是连接池被某个 sql 占满了.
导致正常 sql 也要 2000+ms 才拿到连接并执行, 但是执行是很快的. 你本地 nativecat 快也是因为这个, |
 |
9
HiShan 2021-09-09 12:49:11 +08:00
蹲一个后续 ）
|
 |
10
defunct9 2021-09-09 12:56:12 +08:00 19
开 ssh，让我上去看看
|
|
11
huangmingyou 2021-09-09 13:11:30 +08:00
看 mysql slow log; 把怀疑的微服务停掉
|
 |
12
gBurnX 2021-09-09 13:13:46 +08:00
当复杂系统，不容易及时排查出问题时，其实可以留一手：粗暴的监控大法：
1.能输出日志的 app，全部监控起来。 2.把你们自己写的程序里，每个函数、接口与数据库 rpc 、List/Queue/Cache 等 size，全部监控起来。 3.把 OS 、nginx 、iis 、db 等各种队列 /缓存 /容器 size，全部监控起来。 然后当 size 接近 total lenth 的 80%，以及 rpc 时间超过 3s 时，在监控面板报警。 性能问题，基本上就是这些，监控好了，就不会出现诡异问题了。 |
 |
13
opengps 2021-09-09 13:21:10 +08:00 3
只看表象可以先推测一个可能的原因：直接清空缓存导致的缓存逻辑缺陷。
然后导致访问穿透缓存直达数据库，延伸到数据库压力过大，这个推测符合你说的单条查询也慢，至于重新发包回复，则往往是中断了慢查询占用的连接数等因素可能性比较大 |
|
14
opengps 2021-09-09 13:21:42 +08:00
简单来说，排查一下那些缓存时更新当晚没有及时回填的，可能会找到问题根源
|
|
15
teliang OP |
 |
17
Digitalzz 2021-09-09 13:42:48 +08:00
有没有用 Arthas 查看进入 Mapper 里的具体方法，这里面应该就可以看到是否是获取连接等到太长等问题。
或者说你们的 RDS 上是否可以看到当天连接数量的使用趋势图。 |
 |
18
cxh116 2021-09-09 13:46:36 +08:00
看 web server 的线程数是不是大于数据库连接池的数量?
比如 web server 平常响应很快, 数据库连接很快释放回池. 但因某个查询慢,导致连接释放慢, 在数据连接不够时,其它 web 线程就要等池的连接释放才能够查询. 这就解释为什么 web server 查询慢,但 nativecat 查询快. 只是一种可能,对 java 相关的不太熟悉,供参考. |
|
19
opengps 2021-09-09 13:46:59 +08:00
@teliang 是不是同一个查询链接跟是否同一个方法没有直接关系。这得看数据库访问层面是否同一个数据库查询实例之类的。虽然现在已经恢复了，不过你应该依然可以从 rds 后台查询到故障时段的 iops 指标，硬盘读写指标
|
 |
20
liyunyang 2021-09-09 13:56:45 +08:00
"贴一个监控调用的数据，信息尽量都脱敏了，这是 C 服务 buildUserCacheData 的监控，时间都超过 20 秒了"
问一下楼主这个监控使用什么做的，准备给公司设计一个微服务的监控方案 |
 |
21
twl007 2021-09-09 13:57:44 +08:00 via iPhone 1
当年阿里云遇到过一个类似的事情 也是数据库没有报警 但是速度变得非常慢 导致我们的 redis 里面大量的数据没有写回到 rds
开工单给阿里云 答复说那台 rds 的硬盘出现了问题 已经帮忙做了主从切换 遂解决 😑 |
 |
24
cking 2021-09-09 14:10:40 +08:00 5
我们也遇见过打死整个服务的 具体后面来查的时候 就是因为 tomcat 里面的线程(还是其他啥的) 有 200 个请求等待,导致后续的请求进来了之后就开始排队. 实际上 sql 并不慢 是 tomcat 里面的请求线程满了 你增加了日志以后 打包发版本 相当于就是重启了 tomcat 所以就会释放掉当时请求进来的一些 我们当时是 修改了 tomcat 的最大线程是 800(默认是 200) 后续就再也没有出现过这个问题了
|
 |
25
fkdtz 2021-09-09 14:35:33 +08:00
用的量子计算机？当你试图监控它时，它就表现出相反的结果。
感觉不是这行代码的事儿，当时 DB 的资源占用怎么样？或者连接池被耗尽？猜测耗时大部分是在等待资源。 代码还原到当时的版本，在模拟环境搞个压测看看能否复现？ |
 |
26
Lemeng 2021-09-09 14:44:17 +08:00
@villivateur 真有这种事，离奇
|
 |
27
snownarrow 2021-09-09 14:49:12 +08:00
@defunct9 “开 ssh，让我上去看看” 发现这都快成为你的口头禅了
|
|
29
defunct9 2021-09-09 15:52:12 +08:00
@zhoudaiyu @snownarrow 是我，是我，还是我
|
 |
30
SilenceLL 2021-09-09 16:01:56 +08:00
我们碰到过引用的 mysql 连接池满了， 重启服务以后就好了，，可能应用配置的连接池满了，拿不到连接了，但是 navicat 连接不走应用连接池所以没问题？
|
 |
31
redford42 2021-09-09 16:09:11 +08:00
只有做好监控日志静待复现了
|
 |
32
proxychains 2021-09-09 16:15:45 +08:00
@villivateur 离谱
|
 |
33
Smallsun1231 2021-09-09 16:20:28 +08:00
@defunct9 #10 虽迟但到
|
 |
34
patx 2021-09-09 17:07:06 +08:00 via Android
很多情况下，sql 执行慢不是 sql 有问题，可能是连接池满了，获取新的连接会等待空闲连接。如果一直拿不到，会等到超时。
|
 |
35
lizuoqiang 2021-09-09 17:13:56 +08:00
有没有想过是 K8S 某个 Node 出问题了。
|
 |
36
kindjeff 2021-09-09 17:14:43 +08:00
MySQL 监控没问题么
|
 |
37
popop1 2021-09-09 17:31:31 +08:00
曾经双 11，阿里聚石塔部分硬盘出现过问题.切换后遂解决
|
 |
38
peanutcheeseball 2021-09-09 17:37:59 +08:00
蹲个后续
|
 |
39
zhuweiyou 2021-09-09 17:38:32 +08:00
@villivateur 一样遇到过, 然后把注释删了 也正常了.
|
 |
42
ForkNMB 2021-09-09 18:22:31 +08:00
数据库连接池没有监控吗 CAT 之类的上报有没有
|
 |
43
justNoBody 2021-09-09 18:29:58 +08:00
所以是不是 13 楼说的那个可能性？
|
 |
44
bk201 2021-09-09 18:30:40 +08:00
感觉像是阿里云内部网关问题
|
 |
45
Orlion 2021-09-09 18:39:13 +08:00
Navicat 和微服务查询同一条 SQL 时间差这么多 可能是有慢查询导致连接池满了，请求线程都在等连接。
还是上监控吧😄 |
 |
46
snail00 2021-09-09 18:56:22 +08:00
可能是服务的连接数限制比较小, 清了缓存后, 大量的查询挤占有限的连接数. 大家都在排队等链接.
这个限制保护了 RDS, 应该也不会体现在 RDS 监控中. 新起的服务没有历史包袱就恢复正常了. |
 |
47
fengfisher3 2021-09-09 19:02:24 +08:00
找阿里云问了吗？不太懂什么原因，也蹲个后续。
|
 |
48
Variazioni 2021-09-09 19:50:29 +08:00
建议找个大师给服务器开开光。。
|
 |
49
v2hh 2021-09-09 20:10:17 +08:00
是不是数据库连接池的问题，可以看下 wait 线程的堆栈信息
|
 |
50
railgun 2021-09-09 20:23:22 +08:00
有没有可能之前跑的根本就不是最新代码，所以其实不只是加了一行日志这么简单？
|
 |
51
vindurriel 2021-09-09 20:31:29 +08:00 via iPhone
我猜清空缓存之后问题就会复现 可能是哪个环节有锁 可以找个离线环境压测一下数据库
|
 |
52
HunterPan 2021-09-09 20:57:07 +08:00 via iPhone
慢的话 查看线程栈 一目了然，
|
 |
53
chenshun00 2021-09-09 21:05:43 +08:00
当时的堆栈有没有，目标服务的堆栈，10s 超时，肯定有一些地方阻塞了。顺着链路找应该有下文吧
|
 |
54
palfortime 2021-09-09 21:14:57 +08:00 via Android
应该是代码的问题，某种特定情况触发的吧。132 是 service 不是 mapper 也耗时超过两秒（ 132 那个函数是不是进入会开事务？）。138 那里，一个 service 构造要 10ms 也有点奇怪（有申请什么资源？）。不是启动就应该注入完了？还要动态生成 service ？
|
 |
55
podel 2021-09-09 21:16:25 +08:00
阿里云 rds 有慢日志和 sql 审计功能 都可以开起来看看。
|
 |
56
rekulas 2021-09-09 21:32:58 +08:00
慢的时候，重点检查有没有太多执行中事务，如果没有就考虑连接数不够的问题
|
 |
57
JamChiu 2021-09-09 21:48:19 +08:00 via iPhone
给阿里提个工单压压惊
|
 |
58
hujun528 2021-09-09 22:48:17 +08:00
有点像 数据库 产生 死锁，死锁解除后 查询会恢复正常
|
 |
59
pjntt 2021-09-09 22:55:55 +08:00
“发现主要业务流量入口 M 服务调用 Cache 服务一直超时，调用 C 主要是 M 从 Redis 获取不到用户缓存，需要 C 构建缓存放 Redis 。”
这个明显是缓存击穿了，访问压力直接堆到数据库里。 “构建缓存需要读 8~9 次数据库但是 Dubbo 的超时时间设的是 10s 所以一直超时。” ‘“构建缓存”这里用到事务了吗？如果有事务，那感觉是这个事务执行时间长，导致链接池占满了。 |
 |
60
xupefei 2021-09-10 00:49:20 +08:00 via iPhone 2
提醒一下，在有些公司安全部门点头以前都不算脱敏…
|
 |
61
towry 2021-09-10 08:41:36 +08:00
阿里云的锅
|
 |
62
raptor 2021-09-10 09:17:25 +08:00
有一定概率是阿里云的锅
|
 |
63
Xavi1996 2021-09-10 09:19:20 +08:00
插眼看最后定论
|
 |
64
jorneyr 2021-09-10 09:22:04 +08:00
K8S 的网络很魔幻的，我遇到过从 Pod 内部访问其他 Pod 很慢，从宿主机访问其他 Pod 就正常，而且不是一直这样。
|
 |
65
buster 2021-09-10 09:30:21 +08:00
有个疑问的地方前面有兄弟说是服务连接池被占了，加了日志重新发布链接清掉了，但是前面也重启过啊，感觉对不上。
|
 |
66
bsg1992 2021-09-10 09:38:49 +08:00
不可能是连接池满导致查询满 服务器都重启了。正常来说连接肯定都是释放的。我怀疑是内部网络问题
|
 |
67
pkoukk 2021-09-10 09:53:39 +08:00
瞎猜有一定概率是 K8s 某个 node 到 db 有问题，重启，调度还在这个 node 上
改代码之后是重新部署，调度到了别的 node 上，然后就正常了 |
 |
68
X0ray 2021-09-10 09:54:59 +08:00
有没有看过 redis 连接数，redis 连接泄露的问题需要关注下。
|
 |
69
luwill 2021-09-10 10:09:51 +08:00
大概率 mysql 连接池满了，重启连接池清空了。应该还会复发，看出问题前的请求日志，当天的 mysql 慢日志。
|
 |
70
securityCoding 2021-09-10 10:11:57 +08:00
1. 调用 cache 为什么会超时呢?是不是 redis 没连接了
|
|
71
securityCoding 2021-09-10 10:15:38 +08:00
@luwill 应该不是,看问题描述先从缓存取数据失败(超时)导致大量请求直接查 db 导致 db 压力过大.直接原因大概率是 redis 获取不到连接
|
 |
72
u011631336 2021-09-10 10:17:05 +08:00
大概率是跟数据库有关系，存在锁、事务的原因比较大
|
 |
73
joApioVVx4M4X6Rf 2021-09-10 10:23:25 +08:00
求结果
|
 |
74
repus911 2021-09-10 10:35:27 +08:00
有没有可能是应用数据库链接池设置的比较小
|
 |
75
wineast 2021-09-10 11:00:41 +08:00
大概率是因为重新部署起了作用，而不是那一行代码，至于重新部署部署导致了 node 节点的重新分配还是数据库连接的重新连接，不确定
|
 |
76
3kkkk 2021-09-10 11:37:40 +08:00
通过 actuator 看下每个服务线程占用情况。应该是哪里阻塞了。
|
 |
77
qq1340691923 2021-09-10 13:58:58 +08:00
我也想说连接池打满了，可作者他们试过了重启啊
|
 |
78
superliuliuliu1 2021-09-10 15:33:19 +08:00
是小鹅通吗？听说昨天下午小鹅通崩了
|
 |
79
PDX 2021-09-10 15:39:44 +08:00 via iPhone
如果重新构建缓存，很可能打满连接池，这种情况很常见。
|
 |
80
aoxiansheng 2021-09-10 15:42:15 +08:00 1
数据库也是买的阿里的 RDS 。原来我们的业务用 RDS 就卡死。用自建就正常。
|
 |
81
huxiweng 2021-09-11 10:55:06 +08:00 1
先看看你的 ECS 请求 RDS 有没有超时！
我前段时间被腾讯坑了，原因是 DNS 解析域名失败，赔了我 1500 块云服务器余额。 |
Select Language