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

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

  •  4
     
  •   teliang · 80 天前 · 8292 次点击
    这是一个创建于 80 天前的主题,其中的信息可能已经有所发展或是发生改变。

    环境

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

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

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

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

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

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

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

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

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

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

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

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

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

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