跳至主要內容

JVM故障实践之GC篇

holic-x...大约 13 分钟JAVA基础

JVM故障实践之GC篇

案例:ThreadLocal使用不当,导致内存泄漏,进而触发OOM

1.场景分析

故障问题排查说明

​ 针对CPU飙升问题,可按照相关步骤进行排查,如果确认是由于线程大量GC导致的CPU飙升问题,则可进一步进入GC问题排查

步骤指令说明
1top查看占用cpu高的进程信息
2jstat -gcutil pid查看gc状况
3jmap -dump:format=b,file=name.dump pid导出dump文件
4visualVMMAT工具分析用visualVM分析dump文件

前置准备

以【ThreadLocal使用不当的案例】作为切入点,梳理GC问题排查思路,涉及到的知识点和工具

  • Springboot项目:构建一个http项目,提供测试接口
  • Apifoxopen in new window:接口测试工具(也可使用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测试:

  • 接口测试:【接口管理】模块-创建项目=》创建接口=》输入参数进行访问测试,确认接口是否正常调通
  • 性能测试:【自动化测试】模块=》新建测试场景(输入测试信息)=》选择指定测试场景,添加步骤(可从接口导入)=》输入测试参数模拟测试

image-20240602141231574

image-20240602141447674

本地测试

步骤1:正常启动Springboot项目,随后查看任务管理器的IDEA资源占用情况

​ 为了尽量排查其他因素的干扰,测试的时候尽可能关闭一些无关紧要的进程

image-20240602142644167

步骤2:启动场景测试(模拟1000次、单线程),多次访问接口,查看接口响应情况,并观察CPU占用情况

​ 场景测试启动后,发现CPU迅速飙升

image-20240602143339322

​ 查看控制台日志,发现在某一时刻请求接口访问触发OOM异常,且CPU占用率持续居高不下

image-20240602143240069

​ 结合日志可知,系统触发了OOM异常,且结合测试数据分析,后期的部分接口响应会变得特别慢

image-20240602144023874

​ 查看最终的测试报告

image-20240602144342603

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并上传到服务器运行

image-20240602144932865

【步骤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/

image-20240602152848766

image-20240602152914140

【步骤3】访问部署的项目

​ 使用VM的IP访问部署的项目,测试接口是否可以正常调通,正常访问则可进入下一步场景测试

场景测试

​ VM部署的项目打通访问,进入下一步场景测试。类似上面的步骤创建测试场景(只不过此处的访问URL为上线部署环境的URL),还是一样构建单线程循环1000次进行访问

​ 结合测试结果分析,其是有一个周期性概念(linux上部署分配的资源有限,所以比windows上运行其异常触发得会更快,结果对比也比较明显),前期访问很快,随后访问很慢,待部分CPU资源释放后又恢复了正常访问的速度,然后又变得很慢,循环往复(就会出现系统有时候访问很快、有时候访问很慢的问题),最终导致OOM异常触发

​ 结合下述数据可知:1-9轮接口正常响应,但响应速度越来越慢;10-16轮接口正常响应,响应速度慢慢恢复到一开始的正常状态;

image-20240602154310543

image-20240602154326739

​ 继续访问,随后触发OOM异常,此时查看系统日志信息

image-20240602154647106

image-20240602155028090

​ 查看相应的日志文件,发现Full GC被频繁触发

image-20240602164700402

​ 【步骤1】通过linux系统命令查看进程在整个系统中的内存使用率:top

image-20240602155304322

​ 【步骤2】通过top -Hp pid命令查看具体线程占用系统资源的情况:top -Hp 55533

image-20240602155515864

​ 【步骤3】通过jstack pid指令查看具体线程的堆栈信息(排查是否出现死锁或者I/O阻塞的问题),发现CPU占用过高的进程一直在进行大量的GC

image-20240602155929635

​ 【步骤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版本一致),下载地址参考open in new window

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)

image-20240602161317548

# 下载
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复制到本地

image-20240602183902108

image-20240602184316100

​ 可以根据图示分析占用内存最多的大对象,可以看到Byte数组是占用最多的,但是它的数量才18个,说明是大对象没有得到有效释放导致内存泄漏,点进去查看具体详情,可以看到这些Byte数组就是在接口中定义的Byte[4096*10240]

image-20240602185833180

基于上述思路,梳理了如何线上排查基于GC问题导致的CPU飙升问题,其排查思路其实大同小异,首先是要定位到CPU占用最高的进程,然后依次拆解进程的执行情况

4.Profiler使用

​ 除却可以直接导入分析文件之外,还可结合本地调试分析堆内存分配和占用情况:以下面这种方式启动项目,然后结合场景测试进行调试,可以实时根据CPU、堆内存分配情况

image-20240602191139626

​ 程序执行一段时间后,观察图示,则可解释为什么程序会出现有时候访问很快、有时候访问很慢、有时候访问失败的问题

image-20240602191526590

  • 一开始堆内存占用不多,程序正常响应,但随着访问次数增加,程序的访问越来越慢

  • 当大对象没有得到及时释放,堆内存顶满,这个时候就会触发OOM异常,则接口响应失败

  • 当老年代空间不够,而又需要生成大对象,则在JVM会在某个时机触发Full GC操作(这个操作会暂停所有的用户线程,然后执行回收操作,即可能存在的STW过长会导致程序性能下降),则会出现所谓的访问"时快时满"的情况,因为每个请求进入的时间节点可能不同:

    • 情况1:正常响应:有足够的堆空间可用于分配新对象,且程序正常执行
    • 情况2:响应缓慢:有足够的堆空间可用于分配新对象,但这个时候可能程序恰好在执行Full GC操作,因其STW停顿而导致接口访问性能下降
    • 情况3:响应失败:因为代码的错误引用导致内存泄漏,已经没有足够的堆空间可用,就会导致OOM异常
  • 继续观察,当所有场景测试用例结束之后,没有任何请求,但是堆内存也并没有得到正常释放,进而进一步验证了这是内存泄漏导致的OOM问题

image-20240602192404978

​ 停止记录,随后跟踪信息,可以看到跟踪代码位置提示大部分时间划分在ThreadLocal对象设置的时候,则可思考对应这行代码性能问题

image-20240602193236087

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掉,就可以防止内存泄漏了。

评论
  • 按正序
  • 按倒序
  • 按热度
Powered by Waline v3.1.3