V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
teliang
V2EX  ›  Java

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

  •  4
     
  •   teliang · 2021-09-09 11:48:14 +08:00 · 10040 次点击
    这是一个创建于 931 天前的主题,其中的信息可能已经有所发展或是发生改变。

    环境

    二三十个微服务 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]
    81 条回复    2021-09-11 10:55:06 +08:00
    huangmingyou
        1
    huangmingyou  
       2021-09-09 11:51:15 +08:00
    skywalking 这样的 apm 软件有吗,或者阿里云自己的 apm ; 微服务调用链很复杂的,需要这些工具。
    villivateur
        2
    villivateur  
       2021-09-09 11:54:45 +08:00 via Android
    你这还不算奇怪的,我甚至遇到过加一行注释,问题就突然消失了的
    teliang
        3
    teliang  
    OP
       2021-09-09 11:56:27 +08:00 via iPhone
    @huangmingyou 没有这些工具。。。
    chendy
        4
    chendy  
       2021-09-09 11:56:53 +08:00
    看看 mysql 慢查,看看有没有相关的查询(可能没有)
    可能是应用和数据库之间的网络出了什么问题
    或者应用的连接池配置有问题
    或者是有其他的慢查询拖住了连接池导致后续请求要排队
    可能的点很多很多,慢慢查吧。。。
    kaiger
        5
    kaiger  
       2021-09-09 11:58:03 +08:00
    @villivateur 这就离谱。。。
    soupu626
        6
    soupu626  
       2021-09-09 12:01:39 +08:00   ❤️ 3
    服务 sql 慢,本地查着快
    怀疑有其他的慢 sql 把服务的数据库链接池打满了?
    导致你这个简单 sql 拿不到链接,大量耗时其实是在等待链接,执行时间其实很快和你的本地连上去查是一样的
    akira
        7
    akira  
       2021-09-09 12:02:13 +08:00   ❤️ 1
    和这行代码有关的可能性几乎是 0
    现在移除掉这行代码 估计也是正常的
    zoharSoul
        8
    zoharSoul  
       2021-09-09 12:46:00 +08:00
    应该是连接池被某个 sql 占满了.
    导致正常 sql 也要 2000+ms 才拿到连接并执行, 但是执行是很快的.
    你本地 nativecat 快也是因为这个,
    HiShan
        9
    HiShan  
       2021-09-09 12:49:11 +08:00
    蹲一个后续 )
    defunct9
        10
    defunct9  
       2021-09-09 12:56:12 +08:00   ❤️ 19
    开 ssh,让我上去看看
    huangmingyou
        11
    huangmingyou  
       2021-09-09 13:11:30 +08:00
    看 mysql slow log; 把怀疑的微服务停掉
    gBurnX
        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 时,在监控面板报警。

    性能问题,基本上就是这些,监控好了,就不会出现诡异问题了。
    opengps
        13
    opengps  
       2021-09-09 13:21:10 +08:00   ❤️ 3
    只看表象可以先推测一个可能的原因:直接清空缓存导致的缓存逻辑缺陷。
    然后导致访问穿透缓存直达数据库,延伸到数据库压力过大,这个推测符合你说的单条查询也慢,至于重新发包回复,则往往是中断了慢查询占用的连接数等因素可能性比较大
    opengps
        14
    opengps  
       2021-09-09 13:21:42 +08:00
    简单来说,排查一下那些缓存时更新当晚没有及时回填的,可能会找到问题根源
    teliang
        15
    teliang  
    OP
       2021-09-09 13:26:37 +08:00
    @chendy
    @soupu626
    @zoharSoul
    @opengps
    @gBurnX
    贴了个图,同一个 service 方法多次查询数据库不用每次都从连接池拿吧,应该是复用的才对呀
    zoharSoul
        16
    zoharSoul  
       2021-09-09 13:33:16 +08:00
    @teliang #15 这要看是不是在一个事务里
    Digitalzz
        17
    Digitalzz  
       2021-09-09 13:42:48 +08:00
    有没有用 Arthas 查看进入 Mapper 里的具体方法,这里面应该就可以看到是否是获取连接等到太长等问题。

    或者说你们的 RDS 上是否可以看到当天连接数量的使用趋势图。
    cxh116
        18
    cxh116  
       2021-09-09 13:46:36 +08:00
    看 web server 的线程数是不是大于数据库连接池的数量?
    比如 web server 平常响应很快, 数据库连接很快释放回池.
    但因某个查询慢,导致连接释放慢, 在数据连接不够时,其它 web 线程就要等池的连接释放才能够查询. 这就解释为什么 web server 查询慢,但 nativecat 查询快.
    只是一种可能,对 java 相关的不太熟悉,供参考.
    opengps
        19
    opengps  
       2021-09-09 13:46:59 +08:00
    @teliang 是不是同一个查询链接跟是否同一个方法没有直接关系。这得看数据库访问层面是否同一个数据库查询实例之类的。虽然现在已经恢复了,不过你应该依然可以从 rds 后台查询到故障时段的 iops 指标,硬盘读写指标
    liyunyang
        20
    liyunyang  
       2021-09-09 13:56:45 +08:00
    "贴一个监控调用的数据,信息尽量都脱敏了,这是 C 服务 buildUserCacheData 的监控,时间都超过 20 秒了"

    问一下楼主这个监控使用什么做的,准备给公司设计一个微服务的监控方案
    twl007
        21
    twl007  
       2021-09-09 13:57:44 +08:00 via iPhone   ❤️ 1
    当年阿里云遇到过一个类似的事情 也是数据库没有报警 但是速度变得非常慢 导致我们的 redis 里面大量的数据没有写回到 rds

    开工单给阿里云 答复说那台 rds 的硬盘出现了问题 已经帮忙做了主从切换 遂解决 😑
    teliang
        22
    teliang  
    OP
       2021-09-09 14:01:27 +08:00
    @liyunyang 阿里的 Arthas
    teliang
        23
    teliang  
    OP
       2021-09-09 14:03:23 +08:00
    @zoharSoul #16 窝草,我看了一下,方法没有加事务注解
    cking
        24
    cking  
       2021-09-09 14:10:40 +08:00   ❤️ 5
    我们也遇见过打死整个服务的 具体后面来查的时候 就是因为 tomcat 里面的线程(还是其他啥的) 有 200 个请求等待,导致后续的请求进来了之后就开始排队. 实际上 sql 并不慢 是 tomcat 里面的请求线程满了 你增加了日志以后 打包发版本 相当于就是重启了 tomcat 所以就会释放掉当时请求进来的一些 我们当时是 修改了 tomcat 的最大线程是 800(默认是 200) 后续就再也没有出现过这个问题了
    fkdtz
        25
    fkdtz  
       2021-09-09 14:35:33 +08:00
    用的量子计算机?当你试图监控它时,它就表现出相反的结果。

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

    代码还原到当时的版本,在模拟环境搞个压测看看能否复现?
    Lemeng
        26
    Lemeng  
       2021-09-09 14:44:17 +08:00
    @villivateur 真有这种事,离奇
    snownarrow
        27
    snownarrow  
       2021-09-09 14:49:12 +08:00
    @defunct9 “开 ssh,让我上去看看” 发现这都快成为你的口头禅了
    zhoudaiyu
        28
    zhoudaiyu  
       2021-09-09 14:55:14 +08:00 via iPhone
    @defunct9 哪都能看到你🐶
    defunct9
        29
    defunct9  
       2021-09-09 15:52:12 +08:00
    @zhoudaiyu @snownarrow 是我,是我,还是我
    SilenceLL
        30
    SilenceLL  
       2021-09-09 16:01:56 +08:00
    我们碰到过引用的 mysql 连接池满了, 重启服务以后就好了,,可能应用配置的连接池满了,拿不到连接了,但是 navicat 连接不走应用连接池所以没问题?
    redford42
        31
    redford42  
       2021-09-09 16:09:11 +08:00
    只有做好监控日志静待复现了
    proxychains
        32
    proxychains  
       2021-09-09 16:15:45 +08:00
    @villivateur 离谱
    Smallsun1231
        33
    Smallsun1231  
       2021-09-09 16:20:28 +08:00
    @defunct9 #10 虽迟但到
    patx
        34
    patx  
       2021-09-09 17:07:06 +08:00 via Android
    很多情况下,sql 执行慢不是 sql 有问题,可能是连接池满了,获取新的连接会等待空闲连接。如果一直拿不到,会等到超时。
    lizuoqiang
        35
    lizuoqiang  
       2021-09-09 17:13:56 +08:00
    有没有想过是 K8S 某个 Node 出问题了。
    kindjeff
        36
    kindjeff  
       2021-09-09 17:14:43 +08:00
    MySQL 监控没问题么
    popop1
        37
    popop1  
       2021-09-09 17:31:31 +08:00
    曾经双 11,阿里聚石塔部分硬盘出现过问题.切换后遂解决
    peanutcheeseball
        38
    peanutcheeseball  
       2021-09-09 17:37:59 +08:00
    蹲个后续
    zhuweiyou
        39
    zhuweiyou  
       2021-09-09 17:38:32 +08:00
    @villivateur 一样遇到过, 然后把注释删了 也正常了.
    lei2j
        40
    lei2j  
       2021-09-09 17:42:46 +08:00
    @defunct9 我就服你
    akira
        41
    akira  
       2021-09-09 17:51:58 +08:00
    @kindjeff 用 ui 工具直连 mysql 并且执行正常的话,这种情况下 mysql 就是正常的
    ForkNMB
        42
    ForkNMB  
       2021-09-09 18:22:31 +08:00
    数据库连接池没有监控吗 CAT 之类的上报有没有
    justNoBody
        43
    justNoBody  
       2021-09-09 18:29:58 +08:00
    所以是不是 13 楼说的那个可能性?
    bk201
        44
    bk201  
       2021-09-09 18:30:40 +08:00
    感觉像是阿里云内部网关问题
    Orlion
        45
    Orlion  
       2021-09-09 18:39:13 +08:00
    Navicat 和微服务查询同一条 SQL 时间差这么多 可能是有慢查询导致连接池满了,请求线程都在等连接。

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

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

    ‘“构建缓存”这里用到事务了吗?如果有事务,那感觉是这个事务执行时间长,导致链接池占满了。
    xupefei
        60
    xupefei  
       2021-09-10 00:49:20 +08:00 via iPhone   ❤️ 2
    提醒一下,在有些公司安全部门点头以前都不算脱敏…
    towry
        61
    towry  
       2021-09-10 08:41:36 +08:00
    阿里云的锅
    raptor
        62
    raptor  
       2021-09-10 09:17:25 +08:00
    有一定概率是阿里云的锅
    Xavi1996
        63
    Xavi1996  
       2021-09-10 09:19:20 +08:00
    插眼看最后定论
    jorneyr
        64
    jorneyr  
       2021-09-10 09:22:04 +08:00
    K8S 的网络很魔幻的,我遇到过从 Pod 内部访问其他 Pod 很慢,从宿主机访问其他 Pod 就正常,而且不是一直这样。
    buster
        65
    buster  
       2021-09-10 09:30:21 +08:00
    有个疑问的地方前面有兄弟说是服务连接池被占了,加了日志重新发布链接清掉了,但是前面也重启过啊,感觉对不上。
    bsg1992
        66
    bsg1992  
       2021-09-10 09:38:49 +08:00
    不可能是连接池满导致查询满 服务器都重启了。正常来说连接肯定都是释放的。我怀疑是内部网络问题
    pkoukk
        67
    pkoukk  
       2021-09-10 09:53:39 +08:00
    瞎猜有一定概率是 K8s 某个 node 到 db 有问题,重启,调度还在这个 node 上
    改代码之后是重新部署,调度到了别的 node 上,然后就正常了
    X0ray
        68
    X0ray  
       2021-09-10 09:54:59 +08:00
    有没有看过 redis 连接数,redis 连接泄露的问题需要关注下。
    luwill
        69
    luwill  
       2021-09-10 10:09:51 +08:00
    大概率 mysql 连接池满了,重启连接池清空了。应该还会复发,看出问题前的请求日志,当天的 mysql 慢日志。
    securityCoding
        70
    securityCoding  
       2021-09-10 10:11:57 +08:00
    1. 调用 cache 为什么会超时呢?是不是 redis 没连接了
    securityCoding
        71
    securityCoding  
       2021-09-10 10:15:38 +08:00
    @luwill 应该不是,看问题描述先从缓存取数据失败(超时)导致大量请求直接查 db 导致 db 压力过大.直接原因大概率是 redis 获取不到连接
    u011631336
        72
    u011631336  
       2021-09-10 10:17:05 +08:00
    大概率是跟数据库有关系,存在锁、事务的原因比较大
    v2exblog
        73
    v2exblog  
       2021-09-10 10:23:25 +08:00
    求结果
    repus911
        74
    repus911  
       2021-09-10 10:35:27 +08:00
    有没有可能是应用数据库链接池设置的比较小
    wineast
        75
    wineast  
       2021-09-10 11:00:41 +08:00
    大概率是因为重新部署起了作用,而不是那一行代码,至于重新部署部署导致了 node 节点的重新分配还是数据库连接的重新连接,不确定
    3kkkk
        76
    3kkkk  
       2021-09-10 11:37:40 +08:00
    通过 actuator 看下每个服务线程占用情况。应该是哪里阻塞了。
    qq1340691923
        77
    qq1340691923  
       2021-09-10 13:58:58 +08:00
    我也想说连接池打满了,可作者他们试过了重启啊
    superliuliuliu1
        78
    superliuliuliu1  
       2021-09-10 15:33:19 +08:00
    是小鹅通吗?听说昨天下午小鹅通崩了
    PDX
        79
    PDX  
       2021-09-10 15:39:44 +08:00 via iPhone
    如果重新构建缓存,很可能打满连接池,这种情况很常见。
    aoxiansheng
        80
    aoxiansheng  
       2021-09-10 15:42:15 +08:00   ❤️ 1
    数据库也是买的阿里的 RDS 。原来我们的业务用 RDS 就卡死。用自建就正常。
    huxiweng
        81
    huxiweng  
       2021-09-11 10:55:06 +08:00   ❤️ 1
    先看看你的 ECS 请求 RDS 有没有超时!
    我前段时间被腾讯坑了,原因是 DNS 解析域名失败,赔了我 1500 块云服务器余额。
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   我们的愿景   ·   实用小工具   ·   3230 人在线   最高记录 6543   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 82ms · UTC 11:57 · PVG 19:57 · LAX 04:57 · JFK 07:57
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.