线上问题排查——服务异常下线复盘

一 问题现象

1、现象一(2022年10月14号中午12点23分左右)

2022年10月14号中午12点23分左右,生产环境mc服务突然下线,相关功能全部不可用,监控组件也提示服务下线。

三分钟后,运维先紧急重启了,没有来得及记录当时的dump文件。

image.png

虽然没有dump文件,但是我们还是可以从几个方面去排查的:

(1)、机器环境(磁盘空间、运行内存等)

磁盘空间充足,通过长时间观察运行内存情况、cpu占用情况,也没发现任何异常。

(2)、服务被人为下线或kill

运维通过排查机器运行指令及通过nacos日志也排除了被人为下线和kill的因素。

(3)、JVM内存溢出

通过分析mc当时挂掉的前后日志,没有发现任何异常,-XX:HeapDumpPath=/home/smartcommunity/jvm/dump 目录下也没有任何的dump文件生成,排除了JVM内存溢出的可能。

(4)、tomcat线程数占满了,导致后续服务请求超时,nacos心跳检测服务下线

因为没有当时的dump文件,我们只能通过日志去验证这个猜测,通过查看gateway组件日志,验证确实存在先请求超时,后找不到服务的异常日志,具体查看以下文件。但是这也没法直接验证是因为tomcat线程数满的问题引起的。

因为没有排查依据,这个事情也就先耽搁了,直到。。。。。2022年10月25号

2、现象二(2022年10月25号早上8点40分左右)

2022年10月25号早上8点40分左右,生产mc组件再一次突然下线(监控组件问题,导致这次下线没有发钉钉邮件提醒),可惜的是这次还是没有及时记录下dump文件。

老样子,经过排查排除了JVM内存溢出、机器环境、服务被人为下线等因素。但是我们通过mc组件日志,发现了错误日志。

image.png

因此,我们初步断定是邮件健康检查失败引起的服务下线问题,但是缺少实质性证据,我们只能反证这个结论,当时的验证思路可以查看这篇博客:一次线上问题处理——服务大量网络连接处在close_wait状态

后续经过一系列猜测、模拟、实验等,始终没法证实我们这个结论。

无奈之下,我们只能先将mc的邮件服务关停,如果后续没有发现服务挂掉,那说明确实是邮件健康检查失败引起的服务下线。

3、现象三(2022年11月8号早上9点左右)

2022年11月8号早上9点左右,两台服务器上的mc实例全部下线。因为我们已经关停了邮件服务,这也否定了我们之前的结论(现象二猜测)。

image.png

好在我们这次我们事先搭建了双节点,并且记录下了当时实例1的线程、内存运行情况,保留实例2作为排查目标。这次,我们从头分析一遍。。。

二 确认原因

目前实例2是崩溃现场,我们直接从实例2服务器入手。。

1、问题定位一:垃圾回收线程占用大量cpu资源

因为有前两场事故的经验,很快就排除了JVM内存溢出、服务被人为下线等因素,但是这时候看实例2服务器上的cpu占用情况,我们发现了异常,如下图为cpu占用情况。

image.png

那么,我们看下是哪几个线程占用了这么大的资源

image.png

接下来我们看下这几个线程在做什么事情

image.png

很显然,这几个主要都是垃圾回收线程。说明此刻JVM无法正常进行回收,导致gc线程不断在尝试回收,占用了大量cpu资源。

image.png
列名称 描述
S0 S0(Survivor 0)空间使用百分比(相对于当前容量)
S1 S1(Survivor 1)空间使用百分比(相对于当前容量)
E Eden空间使用百分比(相对于当前容量)
O 老年代空间使用百分比(相对于当前容量)
M 元空间(Metaspace)使用百分比(相对于当前容量)
CCS CCS空间使用百分比
YGC 新生代GC(Minor GC/Young GC)发生的次数
YGCT YGC所消耗的时间, 单位s
FGC Full GC发生的次数
FGCT Full GC消耗的时间, 单位s
GCT 所有GC消耗的总时间, 单位s

2、问题定位二:为什么垃圾回收会频繁执行?什么资源占用了JVM内存?

使用jmap指令dump内存文件,使用分析工具打开后,我们可以发现一个用户tomcat线程占用了大量的内存资源。

image.png

这时候我们看下这个线程对应的堆栈信息


image.png

通过堆栈,可以确定当前占用大量内存资源的线程执行的业务逻辑,那么我们可以尝试复现这个场景。(这边使用的是开发环境模拟)

image.png

然后gg了,mc组件挂了... 查看nginx日志,发现响应状态码499

10.100.25.229 - - [21/Nov/2022:19:34:09 +0800] "POST /web/mc/user/list/by-neigh HTTP/1.1" 499 0 "https://saasdev-54.leelen.net/sc/7183f3cb6f0134deb9940c1123ddb6fe/system/allConfig/process" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36" "-" "30.018" "30.018"

这边有个小插曲,按理来说当前这个请求已经进入mc服务了,那为什么我们没有发现任何请求或者报错日志呢?再怎么样应该也会有请求体的日志的?

原来,之前在针对佛山日志多问题进行改造时,对于日志量大、无关紧要的日志进行了过滤,这样也影响了我们前两次问题的排查。

image.png

三 寻找根源

根据线程堆栈信息,我们可以很快定位到具体的业务代码。如下图为问题接口:/rest/mc/web/user/list/by-neigh的业务方法

image.png

查看该线程的内存占用情况,可以看到QueryWrapper、DynamicContext、StringBuilder对象占了大部分内存,那想必是Mybatis plus在处理in查询时创建出来的对象。

image.png

使用jstack命令分析,发现该线程一直没有释放,处在运行或等待状态。

原因:

处理外部请求的工作线程,由于业务代码上的bug,in查询时传入6万多个小区号,导致MybatisPlus创建了大量对象耗尽堆内存(堆内存原来分配太小256M,正常空闲就几十M),业务逻辑要继续往下走发现内存不足开始gc。

jvm gc线程一直在尝试回收垃圾对象,但是因为线程还没有结束,占据大量堆内存的对象均为GC Roots(工作线程)可达状态,无法被回收。

于是导致两个问题:1、这几个gc线程不断进行垃圾回收占用了大量cpu资源; 2、jvm没有可用堆内存空间给新的请求去使用。

image.png
image.png

四 解决方案

1、该接口不需要小区相关信息,重写一个构造返回体方法

image.png

2、扩大堆内存

由:-Xms256m -Xmx256m

修改为:-Xms2048m -Xmx2048m

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 212,185评论 6 493
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 90,445评论 3 385
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 157,684评论 0 348
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 56,564评论 1 284
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 65,681评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 49,874评论 1 290
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,025评论 3 408
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,761评论 0 268
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,217评论 1 303
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,545评论 2 327
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,694评论 1 341
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,351评论 4 332
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,988评论 3 315
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,778评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,007评论 1 266
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 46,427评论 2 360
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 43,580评论 2 349

推荐阅读更多精彩内容