JVM故障实践之GC篇
JVM故障实践之GC篇
案例:ThreadLocal使用不当,导致内存泄漏,进而触发OOM
1.场景分析
故障问题排查说明
针对CPU飙升问题,可按照相关步骤进行排查,如果确认是由于线程大量GC导致的CPU飙升问题,则可进一步进入GC问题排查
步骤 | 指令 | 说明 |
---|---|---|
1 | top | 查看占用cpu高的进程信息 |
2 | jstat -gcutil pid | 查看gc状况 |
3 | jmap -dump:format=b,file=name.dump pid | 导出dump文件 |
4 | visualVM 、MAT 工具分析 | 用visualVM分析dump文件 |
前置准备
以【ThreadLocal使用不当的案例】作为切入点,梳理GC问题排查思路,涉及到的知识点和工具
- Springboot项目:构建一个http项目,提供测试接口
- Apifox:接口测试工具(也可使用JMeter性能测试工具,但Apifox的功能更加强大)
场景分析:ThreadLocal使用不当,导致内存泄漏,进而触发OOM
模拟对每个线程设置一个本地变量。运行以下代码,访问接口,系统一会儿就发送了内存溢出异常(PS:为了尽快看到对比效果,此处可以适当增大Byte数组大小)
@RequestMapping(value = "/testThreadLocalOom")
public String testThreadLocalOom(HttpServletRequest request) {
ThreadLocal<Byte[]> localVariable = new ThreadLocal<Byte[]>();
localVariable.set(new Byte[4096*1024]);// 为线程添加变量(可适当增大Byte数组大小[4096*1024*10])
return "success";
}
2.测试准备
开发&测试环境构建
测试思路
- 先确认本地环境是否可以测通,并通过Apifox进行性能测试,看能否达到预期的异常效果
- 打包jar并上传到服务器进行测试,随后按照排查思路对线上问题进行排查
构建步骤
创建一个Springboot项目,随后填充接口并访问测试:http://localhost:8080/oom/testThreadLocalOom,使用Apifox测试接口是否可以调通
如果是访问本地接口则需要根据Apifox官方提示安装本地客户端或者在线调用(引入插件)再进行测试,否则提示无法访问。
Apifox测试:
- 接口测试:【接口管理】模块-创建项目=》创建接口=》输入参数进行访问测试,确认接口是否正常调通
- 性能测试:【自动化测试】模块=》新建测试场景(输入测试信息)=》选择指定测试场景,添加步骤(可从接口导入)=》输入测试参数模拟测试
本地测试
步骤1:正常启动Springboot项目,随后查看任务管理器的IDEA资源占用情况
为了尽量排查其他因素的干扰,测试的时候尽可能关闭一些无关紧要的进程
步骤2:启动场景测试(模拟1000次、单线程),多次访问接口,查看接口响应情况,并观察CPU占用情况
场景测试启动后,发现CPU迅速飙升
查看控制台日志,发现在某一时刻请求接口访问触发OOM异常,且CPU占用率持续居高不下
结合日志可知,系统触发了OOM异常,且结合测试数据分析,后期的部分接口响应会变得特别慢
查看最终的测试报告
3.线上排查
步骤 | 说明 |
---|---|
【1】部署并启动项目,需要开启堆内存日志 | 需要开启堆内存日志,观察日志记录信息,后续可借助分析工具分析文件信息 |
【2】启动场景测试:单线程循环1000次 | 观察什么时候出现接口请求调用异常,然后对应跟踪服务器 |
【3】top | 查看内存占用最高的进程 |
【4】top -Hp $pid | 查看内存占用最高的进程相关的线程信息 |
【5】jstack $pid | 查看相关线程的堆栈信息(排查IO阻塞和死锁问题) |
【6】jmap -heap $pid | 查看堆内存占用情况 |
【7】使用内存泄漏分析工具分析文件信息(hprof文件) | 借助idea的Profile工具分析堆内存情况,定位具体信息 |
项目部署
【步骤1】确认本地项目启动正常访问,随后将项目进行package(mvn clean package
),获取到jar并上传到服务器运行
【步骤2】启动项目(此处使用VMWare的虚拟机服务器进行部署)
# jar启动:设定参数配置,开启堆内存异常日志
java -jar -Xms1000m -Xmx4000m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/noob/logs/oomDemo/heapdump.hprof -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/home/noob/logs/oomDemo/heapTest.log OomDemo-0.0.1-SNAPSHOT.jar
启动如果提示没有主清单属性,则需要检查pom.xml配置,确认mainClass配置(将<skip>
的true配置给注释掉即可)
需确认日志文件存储目录(此处指定日志文件存储目录:/home/noob/logs/oomDemo/
)
【步骤3】访问部署的项目
使用VM的IP访问部署的项目,测试接口是否可以正常调通,正常访问则可进入下一步场景测试
场景测试
VM部署的项目打通访问,进入下一步场景测试。类似上面的步骤创建测试场景(只不过此处的访问URL为上线部署环境的URL),还是一样构建单线程循环1000次进行访问
结合测试结果分析,其是有一个周期性概念(linux上部署分配的资源有限,所以比windows上运行其异常触发得会更快,结果对比也比较明显),前期访问很快,随后访问很慢,待部分CPU资源释放后又恢复了正常访问的速度,然后又变得很慢,循环往复(就会出现系统有时候访问很快、有时候访问很慢的问题),最终导致OOM异常触发
结合下述数据可知:1-9轮接口正常响应,但响应速度越来越慢;10-16轮接口正常响应,响应速度慢慢恢复到一开始的正常状态;
继续访问,随后触发OOM异常,此时查看系统日志信息
查看相应的日志文件,发现Full GC被频繁触发
【步骤1】通过linux系统命令查看进程在整个系统中的内存使用率:top
【步骤2】通过top -Hp pid
命令查看具体线程占用系统资源的情况:top -Hp 55533
【步骤3】通过jstack pid
指令查看具体线程的堆栈信息(排查是否出现死锁或者I/O阻塞的问题),发现CPU占用过高的进程一直在进行大量的GC
【步骤4】通过jmap
查看堆内存的使用情况:jamp -heap 55533
Debugger attached successfully.
Server compiler detected.
JVM version is 25.402-b06
using thread-local object allocation.
Parallel GC with 4 thread(s)
Heap Configuration:
MinHeapFreeRatio = 0
MaxHeapFreeRatio = 100
MaxHeapSize = 4194304000 (4000.0MB)
NewSize = 349175808 (333.0MB)
MaxNewSize = 1397751808 (1333.0MB)
OldSize = 699400192 (667.0MB)
NewRatio = 2
SurvivorRatio = 8
MetaspaceSize = 21807104 (20.796875MB)
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 17592186044415 MB
G1HeapRegionSize = 0 (0.0MB)
Heap Usage:
Exception in thread "main" java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at sun.tools.jmap.JMap.runTool(JMap.java:201)
at sun.tools.jmap.JMap.main(JMap.java:130)
Caused by: java.lang.RuntimeException: unknown CollectedHeap type : class sun.jvm.hotspot.gc_interface.CollectedHeap
at sun.jvm.hotspot.tools.HeapSummary.run(HeapSummary.java:144)
at sun.jvm.hotspot.tools.Tool.startInternal(Tool.java:260)
at sun.jvm.hotspot.tools.Tool.start(Tool.java:223)
at sun.jvm.hotspot.tools.Tool.execute(Tool.java:118)
at sun.jvm.hotspot.tools.HeapSummary.main(HeapSummary.java:49)
... 6 more
此处使用jmap指令出现异常,需要确认jdk版本(此处使用的openjdk 1.8.0_402
),因为-heap参数会调用到sun.jvm
下的debug包,而默认的openJDK并不包含这个调试包
ubuntu系统解决方案:针对Ubuntu系统且JDK版本为1.8,导入openjdk-8-dbg包即可
sudo apt install openjdk-8-dbg
Centos系统解决方案:
因此需要下载一个插件java-openjdk-debug(确保和jdk版本一致),下载地址参考
noob@noob-virtual-machine:~/logs/oomDemo$ java -version
openjdk version "1.8.0_402"
OpenJDK Runtime Environment (build 1.8.0_402-8u402-ga-2ubuntu1~22.04-b06)
OpenJDK 64-Bit Server VM (build 25.402-b06, mixed mode)
# 下载
wget http://debuginfo.centos.org/7/x86_64/java-1.8.0-openjdk-debuginfo-1.8.0.402.b06-1.el7_9.x86_64.rpm
# 安装(先安装rpm指令:sudo apt install rpm)
rpm -ivh java-1.8.0-openjdk-debuginfo-1.8.0.402.b06-1.el7_9.x86_64.rpm
# 安装可能比较慢,需要耐心等待,安装完成后再次访问指令进行测试jmap -heap 55533
noob@noob-virtual-machine:~/logs/oomDemo$ sudo jmap -heap 55533
Attaching to process ID 55533, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.402-b06
using thread-local object allocation.
Parallel GC with 4 thread(s)
Heap Configuration:
MinHeapFreeRatio = 0
MaxHeapFreeRatio = 100
MaxHeapSize = 4194304000 (4000.0MB)
NewSize = 349175808 (333.0MB)
MaxNewSize = 1397751808 (1333.0MB)
OldSize = 699400192 (667.0MB)
NewRatio = 2
SurvivorRatio = 8
MetaspaceSize = 21807104 (20.796875MB)
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 17592186044415 MB
G1HeapRegionSize = 0 (0.0MB)
Heap Usage:
PS Young Generation
Eden Space:
capacity = 262144000 (250.0MB)
used = 167982136 (160.20024871826172MB)
free = 94161864 (89.79975128173828MB)
64.0800994873047% used
From Space:
capacity = 43515904 (41.5MB)
used = 0 (0.0MB)
free = 43515904 (41.5MB)
0.0% used
To Space:
capacity = 9961472 (9.5MB)
used = 131072 (0.125MB)
free = 9830400 (9.375MB)
1.3157894736842106% used
PS Old Generation
capacity = 2796552192 (2667.0MB)
used = 2693203592 (2568.439094543457MB)
free = 103348600 (98.56090545654297MB)
96.30442799188066% used
12485 interned Strings occupying 1132680 bytes.
结合堆内存的情况分析,老年代的占用基本一直拉满,资源始终没有得到释放,由此判断系统发生了内存泄漏,因此要确认具体是什么对象一直无法回收导致内存泄漏
【步骤5】查看具体的堆内存对象(确认是哪个对象占用了堆内存),通过jmap查看存活对象的数量
noob@noob-virtual-machine:~/logs/oomDemo$ jmap -histo:live 55533
num #instances #bytes class name
----------------------------------------------
1: 18 2852128032 [Ljava.lang.Byte;
2: 29207 2709160 [C
3: 6765 747184 java.lang.Class
4: 29139 699336 java.lang.String
5: 20012 640384 java.util.concurrent.ConcurrentHashMap$Node
6: 1992 431464 [B
7: 5674 295264 [Ljava.lang.Object;
8: 3136 282072 [I
9: 5968 238720 java.util.LinkedHashMap$Entry
10: 14082 225312 java.lang.Object
11: 120 199040 [Ljava.util.concurrent.ConcurrentHashMap$Node;
12: 2106 187312 [Ljava.util.HashMap$Node;
结合内容可分析,是Byte对象占用内容明显异常,则说明代码中的Byte对象存在内存泄漏,因此需进一步排查项目中哪里引用到了Byte对象
【步骤6】使用内存泄漏分析工具分析文件信息
- eclipse:通过MAT(Memory Analyzer Tool)工具打开dump的内存日志文件(.hprof文件)
- idea:通过idea自带的内存泄漏分析工具,例如MAT(Eclipse Memory Analyzer)、VisualVM、YourKit Java Profiler
此处使用idea的Profiler:要使用CPU Profiler,IntelliJ IDEA 中打开「Run」菜单,然后选择「Profile CPU」。还可以在「View」菜单中选择「Tool Windows」,并选择「CPU Profiler」,以显示该工具的图形界面。生成的hprof文件有点大,使用VMWare Tools复制到本地
可以根据图示分析占用内存最多的大对象,可以看到Byte数组是占用最多的,但是它的数量才18个,说明是大对象没有得到有效释放导致内存泄漏,点进去查看具体详情,可以看到这些Byte数组就是在接口中定义的Byte[4096*10240]
基于上述思路,梳理了如何线上排查基于GC问题导致的CPU飙升问题,其排查思路其实大同小异,首先是要定位到CPU占用最高的进程,然后依次拆解进程的执行情况
4.Profiler使用
除却可以直接导入分析文件之外,还可结合本地调试分析堆内存分配和占用情况:以下面这种方式启动项目,然后结合场景测试进行调试,可以实时根据CPU、堆内存分配情况
程序执行一段时间后,观察图示,则可解释为什么程序会出现有时候访问很快、有时候访问很慢、有时候访问失败的问题
一开始堆内存占用不多,程序正常响应,但随着访问次数增加,程序的访问越来越慢
当大对象没有得到及时释放,堆内存顶满,这个时候就会触发OOM异常,则接口响应失败
当老年代空间不够,而又需要生成大对象,则在JVM会在某个时机触发Full GC操作(这个操作会暂停所有的用户线程,然后执行回收操作,即可能存在的STW过长会导致程序性能下降),则会出现所谓的访问"时快时满"的情况,因为每个请求进入的时间节点可能不同:
- 情况1:正常响应:有足够的堆空间可用于分配新对象,且程序正常执行
- 情况2:响应缓慢:有足够的堆空间可用于分配新对象,但这个时候可能程序恰好在执行Full GC操作,因其STW停顿而导致接口访问性能下降
- 情况3:响应失败:因为代码的错误引用导致内存泄漏,已经没有足够的堆空间可用,就会导致OOM异常
继续观察,当所有场景测试用例结束之后,没有任何请求,但是堆内存也并没有得到正常释放,进而进一步验证了这是内存泄漏导致的OOM问题
停止记录,随后跟踪信息,可以看到跟踪代码位置提示大部分时间划分在ThreadLocal对象设置的时候,则可思考对应这行代码性能问题
5.如何解决?
对于程序时快时慢时坏的情况,可能最常见的操作就是重启就完事,但实际上问题还是反反复复实际存在的,要做的应该是知其然并且知其所以然,找出症结然后去解决它
基于上述分析,可以得出由于ThreadLocal引用不当,进而导致内存泄漏,最终触发OOM。则此处可思考为什么会出现这个问题?且如何去处理它。
结合源码分析:ThreadLocal是基于ThreadLocalMap实现的,这个Map的Entry继承了WeakReference,而Entry对象中的key使用了WeakReference封装,也就是说Entry中的key是一个弱引用类型,而弱引用类型只能存活在下次GC之前。也就是说当一个对象只有弱引用的时候,只要发生垃圾回收gc,就会被回收。
如果一个线程调用ThreadLocal的set设置变量,当前ThreadLocalMap则新增一条记录,此时ThreadLocal实例没有外部强引用,当发生一次垃圾回收,此时key值被回收,而value值依然存在内存中,由于当前线程一直存在,所以value值将一直被引用。这些被垃圾回收掉的key就存在一条引用链的关系一直存在:Thread => ThreadLocalMap=>Entry=>Value,这条引用链会导致Entry不会回收,Value也不会回收,但Entry中的Key却已经被回收的情况,从而造成内存泄漏。
解决方案:只需要在使用完该key值之后,通过remove方法及时remove掉,就可以防止内存泄漏了。