一 问题现象
1、现象一(2022年10月14号中午12点23分左右)
2022年10月14号中午12点23分左右,生产环境mc服务突然下线,相关功能全部不可用,监控组件也提示服务下线。
三分钟后,运维先紧急重启了,没有来得及记录当时的dump文件。
虽然没有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组件日志,发现了错误日志。
因此,我们初步断定是邮件健康检查失败引起的服务下线问题,但是缺少实质性证据,我们只能反证这个结论,当时的验证思路可以查看这篇博客:一次线上问题处理——服务大量网络连接处在close_wait状态
后续经过一系列猜测、模拟、实验等,始终没法证实我们这个结论。
无奈之下,我们只能先将mc的邮件服务关停,如果后续没有发现服务挂掉,那说明确实是邮件健康检查失败引起的服务下线。
3、现象三(2022年11月8号早上9点左右)
2022年11月8号早上9点左右,两台服务器上的mc实例全部下线。因为我们已经关停了邮件服务,这也否定了我们之前的结论(现象二猜测)。
好在我们这次我们事先搭建了双节点,并且记录下了当时实例1的线程、内存运行情况,保留实例2作为排查目标。这次,我们从头分析一遍。。。
二 确认原因
目前实例2是崩溃现场,我们直接从实例2服务器入手。。
1、问题定位一:垃圾回收线程占用大量cpu资源
因为有前两场事故的经验,很快就排除了JVM内存溢出、服务被人为下线等因素,但是这时候看实例2服务器上的cpu占用情况,我们发现了异常,如下图为cpu占用情况。
那么,我们看下是哪几个线程占用了这么大的资源
接下来我们看下这几个线程在做什么事情
很显然,这几个主要都是垃圾回收线程。说明此刻JVM无法正常进行回收,导致gc线程不断在尝试回收,占用了大量cpu资源。
列名称 | 描述 |
---|---|
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线程占用了大量的内存资源。
这时候我们看下这个线程对应的堆栈信息
通过堆栈,可以确定当前占用大量内存资源的线程执行的业务逻辑,那么我们可以尝试复现这个场景。(这边使用的是开发环境模拟)
然后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服务了,那为什么我们没有发现任何请求或者报错日志呢?再怎么样应该也会有请求体的日志的?
原来,之前在针对佛山日志多问题进行改造时,对于日志量大、无关紧要的日志进行了过滤,这样也影响了我们前两次问题的排查。
三 寻找根源
根据线程堆栈信息,我们可以很快定位到具体的业务代码。如下图为问题接口:/rest/mc/web/user/list/by-neigh的业务方法
查看该线程的内存占用情况,可以看到QueryWrapper、DynamicContext、StringBuilder对象占了大部分内存,那想必是Mybatis plus在处理in查询时创建出来的对象。
使用jstack命令分析,发现该线程一直没有释放,处在运行或等待状态。
原因:
处理外部请求的工作线程,由于业务代码上的bug,in查询时传入6万多个小区号,导致MybatisPlus创建了大量对象耗尽堆内存(堆内存原来分配太小256M,正常空闲就几十M),业务逻辑要继续往下走发现内存不足开始gc。
jvm gc线程一直在尝试回收垃圾对象,但是因为线程还没有结束,占据大量堆内存的对象均为GC Roots(工作线程)可达状态,无法被回收。
于是导致两个问题:1、这几个gc线程不断进行垃圾回收占用了大量cpu资源; 2、jvm没有可用堆内存空间给新的请求去使用。
四 解决方案
1、该接口不需要小区相关信息,重写一个构造返回体方法
2、扩大堆内存
由:-Xms256m -Xmx256m
修改为:-Xms2048m -Xmx2048m