跳至主要內容

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文件
4visualVM、MAT工具分析用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掉，就可以防止内存泄漏了。

0  字
评论
  • 按正序
  • 按倒序
  • 按热度
Powered by Waline v3.1.3
一人の境 Copyright © 2019-未知 holic-x
Copyright © 2024 holic-x