【生产事故】java服务CPU占用过高 复盘一次生产事故问题排查
前言:随着 AI 的发展,日常开发中想必大家都已经用上了 AI,但是生产事故仍然依赖人工经验去排查。这也是 AI 很难完全替代人的一个场景,毕竟不可能让 Agent 直接连接生产环境进行操作,这存在较大的风险。
由于生产事故的诱因千千万,本文也无法覆盖所有场景,主要记录一次实际生产事故的排查过程,并提供一种排查思路。
表现现象:java项目报大量错误,redis连接失败、JDBC连接异常,CPU飙升
由于项目本身并没有达到高并发级别,只是偶尔存在并发,请求数也远没有达到能够将 Redis 击穿的程度。
因此,排查时不能只关注最终表现出来的异常。
Redis 和 JDBC 连接失败,很可能只是因为:
CPU 长时间处于高负载状态,导致 JVM 没有足够的处理能力处理正常请求。
cpu占用过高,大多数时候我们可能会想到arthas,但是这里需要注意一点,如果服务本身在高负载的时候,arthas是及其可能连不上的,而且很多场景arthas并没有想象中好用。
输出线程dump信息和cpu占用信息
top使用top命令,能看到cpu占用情况,找到该项目的pid
(或者ps -ef | grep 都可以,方式多样)
我们假设pid是30314,执行命令
readlink -f /proc/30314/exe例如返回/data/jdk1.8.0_261/bin/java,表示该服务被哪个jdk启动(适用于服务器有多个jdk场景)
如果是容器启动,则需要先找到容器宿主机之间的路径映射。
输入以下命令,表示将pid=30314的项目线程dump,输出至/tmp/目录下的thread-30314.log文件中
/data/jdk1.8.0_261/bin/jcmd 30314 Thread.print > /tmp/thread-30314.log 2>&1使用top命令 找到cpu占用高的线程
top -Hp 30314 -b -n 1 > /tmp/top-30314.txt打开后能看到类似以下信息:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 30316 deity 20 0 8181972 5.5g 14296 R 68.8 17.7 16:18.63 java 30318 deity 20 0 8181972 5.5g 14296 R 68.8 17.7 16:10.66 java 30319 deity 20 0 8181972 5.5g 14296 R 68.8 17.7 16:14.22 java 30317 deity 20 0 8181972 5.5g 14296 R 62.5 17.7 16:15.18 java 30320 deity 20 0 8181972 5.5g 14296 S 18.8 17.7 4:26.14 java 30324 deity 20 0 8181972 5.5g 14296 S 6.2 17.7 7:04.65 java这个命令展示的PID其实是TID (线程id),下文用TID代替 防止概念混淆。
我们以TID=30316分析,将它转成16进制得到 0x766c,在thread-30314.log中搜索,发现结果是
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f708c01e800 nid=0x766c runnable类似的 其它几个TID搜索后发现 也是gc线程,所以很明显,是由于gc负载过大 导致CPU飙升;但gc也只是表现结果,我们需要知道是什么代码导致了gc困难。
分析到这里我们会发现 会有两种场景:
① 业务线程(我们自己写的代码线程)导致CPU飙升
② GC线程导致CPU飙升
如果是业务线程,那么这个时候基本就能知道是什么代码导致的了,不幸的是 博主遇到的场景是业务线程负载已经结束 是GC困难;
所以此时看top命令,看arthas的memory也好 thread也罢,已经看不出真正的诱因,这也是前文提到有些场景arthas没想象中好用的原因。
分析profiler 和 heapdump
到这里已经算是难点了,我们或许看过很多去找哪个线程导致cpu过高的实战案例,可是如果这个业务线程结束了,我们就应该转变思路去分析内存了。
profiler在本案例中 作用较小 作为常用手段 这里也一并补充
开始采集火焰图:
profiler start过30s 或1-2分钟务必及时停止采集(结合自己项目情况估算,主要是需要一个时间窗口来收集内存信息 )
停止采集火焰图 并输出至/tmp/目录
profiler stop --format html --file /tmp/gc.htmlprofiler 是告诉我们 什么代码正在生成对象,导致GC过多;前文提过,业务线程已经执行完了,是残留的内存,所以我们需要将Heap Dump输出。
将heap dump输出至 /tmp/目录 (arthus里面执行)
heapdump /tmp/heap.hprofjdk原生:(以jdk路径/data/jdk1.8.0_261 pid=9815为例)
/data/jdk1.8.0_261/bin/jmap -dump:format=b,file=/tmp/heap.hprof 9815这个文件非常大,占用的堆内存多大 它就多大,从堡垒机等中间服务直接下载回本地可能失败,可以切割下载
注意hprof是二进制文件 不能简单切割 一定要 -b切割
split -b 500M heap.hprof heap.hprof.part-执行完成后检查:
ls -lh heap-live.hprof*应该看到(假设大小为1.5G 切割成3份):
heap-live.hprof heap-live.hprof.part-aa heap-live.hprof.part-ab heap-live.hprof.part-ac下载回本地后 再合并:
windows(注意需要合并的文件名,替换成真实的):
copy /b heap-live.hprof.part-aa+heap-live.hprof.part-ab+heap-live.hprof.part-ac heap-live.hproflinux:
cat heap-live.hprof.part-* > heap-live.hprof接着需要下载eclipse MAT,将合并后的文件通过MAT打开,如果合并错误 MAT会打开失败,且MAT本身需要分配较大内存,否则同样无法打开。
通过MAT的Histogram ,See stacktrace
通过引用链 可以进一步定位 :到底是什么业务代码一直持有这些数据 (至此则是MAT工具的使用,本文不过多阐述,可以结合AI分析)
经过排查后 发现是 导出接口导致,大批量数据,查询中大量对象转换、时间转换,且持续引用list无法释放;业务人员在点击导出 没得到响应后又重复发起了多次导出,直接导致gc拉满。
这也给出警示:在大批量导出接口时,需要加锁,避免同时/重复操作
本次事故流程:
业务代码大批量数据持有对象引用->
堆内存拉满->
gc负载高->
cpu过高导致->j
dbc/redis连接失败->
服务不可用