JVM性能分析 | 一次生产系统Full GC问题分析与排查总结

分手后的思念是犯贱 2022-05-14 12:27 253阅读 0赞

# **一次生产系统Full GC问题分析与排查总结** #

# **背景** #

最近某线上业务系统生产环境频频CPU使用率过低，频繁告警，通过重启可以缓解，但是过了一段时间又会继续预警，线上两个服务节点相继出现CPU资源紧张，导致服务器卡死不可用，通过告警信息可以看到以下问题：  
![这里写图片描述][70]  
从上图可以看到，目前zabbix监控展示CPU空闲时间已经低于预警线，证明目前CPU资源占用过高，考虑到最近并没有特别开发任务上线，但是最近有发布过一个新的营销活动，有可能是因为突然用户量增长进一步凸显该问题。

从Pinpoint APM监控工具看到，从9月3号下午开始，系统开始出现频繁full gc的情况，而刚好9月3号下午发布了一个新活动，基本可以断定这可能是用户量突然激增，凸显潜伏已久的系统问题，于是接下来方向就可以往full gc方向去排查，找出引起full gc的代码。  
![这里写图片描述][70 1]

--------------------

# **侦查思路** #

往FULL GC方向侦查，怀疑存在内存泄露

--------------------

# **排查路线：** #

既然上面已经定位到是FULL GC问题，我们就可以用常用FULL GC的手段去解决。在这次故障分析我们是利用MAT去做分析，主要对以下几点做排查：

*  程序是否内存泄露
 *  程序中是否存在不合理的大对象占用
 *  程序中部分对象产生内存是否可以优化

--------------------

### **导出JVM dump文件和jstack线程日志,保留案发现场** ###

因为公司不允许个人访问线上服务器，于是让运维同学在服务器出现故障时导出jvm dump文件和jstack线程日志，如果自己有权限去生产服务器的话，可以通过以下指令导出jvm dump文件

jmap -dump:format=b,file=文件名 [服务进程ID]

### **结合MAT分析工具，找出可疑对象** ###

使用MAT前，先简单介绍下MAT的一些常用的指标和功能概念：

*  **Shallow Heap指标**：对象本身占用内存的大小，不包含对其他对象的引用，也就是对象头加成员变量（不是成员变量的值）的总和
 *  **Retained Heap指标**：是该对象自己的shallow size，加上从该对象能直接或间接访问到对象的shallow size之和。换句话说，retained size是该对象被GC之后所能回收到内存的总和。
 *  **Histogram动作**：列出每个类的实例数
 *  **Dominator Tree动作**：列出`最大的对象`以及它们保存的内容
 *  **Top Consumers动作**: 按照类和包分组打印花费最高的实例
 *  **Duplicate Classes动作**: 检测由多个类加载器加载的类
 *  **Leak Suspects报告**: 包括泄密嫌疑人和系统概述
 *  **Top Components报告**：列出大于总堆的1％的组件的报告

--------------------

### **通过Leak Suspects排查内存泄露** ###

在**Ecplise Memory Analyzer**导入JVM dump文件，点击工具栏上的 Leak Suspects 菜单项来生成内存泄露分析报告，也可以直接点击饼图下方的 `Reports->Leak Suspects`链接来生成报告。如图：  
![这里写图片描述][70 2]  
MAT工具分析了heap dump后在界面上非常直观的展示了一个饼图，该图深色区域被怀疑有内存泄漏，可以发现整个heap才1.5G内存，深色区域就占了57.76%。接下来是一个简短的描述，MAT告诉我们存在两个可疑问题  
\- **Problem Suspect 1**：告诉我们`java.lang.Thread`线程实例占用了大量内存，一共存在`5154`个实例，并且明确指出`system class loader`加载的`java.lang.Thread`实例占据了`643,021,136 (41.03%)字节` ，并建议用关键字”java.lang.Thread”进行检查。所以，MAT通过简单的两句话就说明了问题所在，就算使用者没什么处理内存问题的经验。在下面还有一个”Details”链接，MAT给了一个参考类。如图：

![这里写图片描述][70 3]

*  **Problem Suspect 2**: 告诉我们`jdk.nashorn.internal.runtime.Context`线程实例占用了大量内存,并且明确指出`sun.misc.Launcher$ExtClassLoader @ 0x9000cf78`加载的`jdk.nashorn.internal.runtime.Context`实例占据了`262,229,320 (16.73%)字节`，并建议用关键字`sun.misc.Launcher$ExtClassLoader @ 0x9000cf78 jdk.nashorn.internal.runtime.Context`进行检查

--------------------

### **通过Top Consumers定位大对象** ###

点击***Actions->Top Consumers*** ，查看大对象有哪些  
![这里写图片描述][70 4]  
![这里写图片描述][70 5]  
![这里写图片描述][70 6]  
从上图可以看出，`java.lang.Thread`、`jdk.nashorn.*`和`javax.script.*`这些类实例占据了大部分内存

--------------------

# **问题分析** #

**从上面分析报告，可疑大胆推断以下结论：**

*  大量`java.lang.Thread`实例，明显是线程使用不合理，怀疑有地方不断创建线程，没有使用线程池导致
 *  大量`jdk.nashorn.internal.*`和`javax.script.*`相关实例，而`jdk.nashorn.*`这个包是Nashorn JavaScript引擎的包，主要是nashorn用于在JVM上以原生方式运行动态的JavaScript代码来扩展Java的功能，`javax.script`包用于javascript与java交互操作。于是可以基本断定这是跟javascript脚本相关操作有关，应该是有地方不断创建javascript脚本相关对象没有被回收。

结合以上两点，推测应用程序线程和脚本操作部分出现问题，与该系统相关开发人员沟通，确实该系统是有大量javascript脚本操作，是通过Javascript脚本做一些特性开发，然后在在java调用执行。尝试使用包名`jdk.nashorn`查找运维导出的jstack线程日志，看看最接近的业务代码是什么  
![这里写图片描述][70 7]

果然看到了线程日志里面找到了疑似线程操作的业务代码，通过查看源码，一步步查看调用链，发现了有个地方会每次实例初始化都会创建一份脚本引擎  
![这里写图片描述][70 8]  
![这里写图片描述][70 9]  
这段代码大概作用是把每个任务的规则脚本存放在脚本引擎，然后存放在`threadLocal`里，每个`MissionEventHandler`实例初始化都会创建一个`threadLocal`用于存放当前线程任务脚本，以防多线程操作同一个`MissionEventHandler`实例会引起脚本因并发被篡改问题。而经过沿着调用链查看源码了解，这些`MissionEventHandler`实例只会业务人员点击任务下线的时候才会进行销毁处理，那就是只要任务不下线，这些任务会一直存活在内存中。

但是只要`MissionEventHandler`实例数量控制好，应该是不会出现上述大量脚本相关实例引发频繁FULL GC问题，接下来我们的侦查方向就是查看`MissionEventHandler`实例创建源头，是否系统存在批量创建该实例的代码？继续沿着调用链查看源代码，发现了一个异步观察者类，它是用来通知消息事件的，以下是其中一个方法  
![这里写图片描述][70 10]  
这里是使用了`CompletableFuture`的`supplyAsync(Supplier<U> supplier)`方法进行异步处理，再进一步查看`supplyAsync`的源码  
![这里写图片描述][70 11]  
![这里写图片描述][70 12]  
![这里写图片描述][70 13]  
从上面代码可以看到，`supplyAsync`有2个重载方法，当我们不指定线程池，它默认是调用第一个方法，当`ForkJoinPool.getCommonPoolParallelism() > 1`才会使用commonPool线程池，否则该方法默认会每次创建一条新的线程去处理。那有没有可能是`ForkJoinPool.getCommonPoolParallelism()<=1` **导致每次都创建新的线程呢?**我们进一步查看`ForkJoinPool.getCommonPoolParallelism()`源码，发现这方法使用Java 8中的`ForkJoinPool.commonPool()`可以使用一个特殊的ForkJoinPool。该池使用一个取决于可用内核数量的预设并行度。一般情况下，预设的并行度是**CPU内核数-1**，该系统在生产环境运行的服务器核数为2，那就是并行度为1，即这里的`ForkJoinPool.getCommonPoolParallelism()=1`,意味着`CompletableFuture`的`supplyAsync`方法在这里处理业务是每次都创建一条新的线程去处理。

--------------------

# **总结** #

根据上面的分析，一切都真相大白，之前看到的大量`java.lang.Thread`实例就是因为处理业务时，默认每次都会开启一条新的线程，导致出现大量的线程实例，而这些大量的线程实例又会引发大量的通知消息操作，导致持有的脚本相关实例没法被回收，从而引发了大量`jdk.nashorn.internal.*`和`javax.script.*` 的实例占据堆内存。

--------------------

# **解决方案** #

这里的解决方案很简单，这里引发的问题都是因为没有使用到线程池导致的，可以采取以下两种措施:

*  通过在tomcat配置jvm启动参数`-Djava.util.concurrent.ForkJoinPool.common.parallelism=2`,可以让`supplyAsync(Supplier<U> supplier)`方法启动默认的`ForkJoinPool.commonPool()`去执行
 *  改为调用`CompletableFuture<U> supplyAsync(Supplier<U> supplier,Executor executor)`，给方法指定线程池**(推荐)**

在本次改造是使用第二个方案，创建了一个自定义线程池，然后指定线程池去执行操作，代码如下  
![这里写图片描述][70 14]  
![这里写图片描述][70 15]

--------------------

# **上线后观察监控** #

上线后通过PINPOINT观察，再也没出现FULL GC问题  
![这里写图片描述][70 16]

--------------------

# **Java引用法则说明** #

从最强到最弱，不同的引用（可到达性）级别反映了对象的生命周期。

*  Strong Ref(强引用)：通常我们编写的代码都是Strong Ref，于此对应的是强可达性，只有去掉强可达，对象才被回收。
 *  Soft Ref(软引用)：对应软可达性，只要有足够的内存，就一直保持对象，直到发现内存吃紧且没有Strong Ref时才回收对象。一般可用来实现缓存，通过java.lang.ref.SoftReference类实现。
 *  Weak Ref(弱引用)：比Soft Ref更弱，当发现不存在Strong Ref时，立刻回收对象而不必等到内存吃紧的时候。通过java.lang.ref.WeakReference和java.util.WeakHashMap类实现。
 *  Phantom Ref(虚引用)：根本不会在内存中保持任何对象，你只能使用Phantom Ref本身。一般用于在进入finalize()方法后进行特殊的清理过程，通过 java.lang.ref.PhantomReference实现。

[70]: /images/20220514/16caa82853794ab79e0cb842131a7828.png
[70 1]: /images/20220514/3120c2445e41481db339f4ec1cd421a1.png
[70 2]: /images/20220514/453a8c2d900249fea7301388c925259b.png
[70 3]: /images/20220514/4b323a0543df45c7b742aea8fba4e4e3.png
[70 4]: /images/20220514/f821453dbede44f8a2058f1c73ecd1ae.png
[70 5]: /images/20220514/46b6ada7c1ae4664a9dab36d1a247764.png
[70 6]: /images/20220514/6b489f69732d4467b711299806af50fc.png
[70 7]: /images/20220514/9e9ca7dfff7a43bdb3467bb713f6da69.png
[70 8]: /images/20220514/92f3c960a6f844f7a23f072bbe4a911e.png
[70 9]: /images/20220514/b3aa17dd984f4165b5100a9b49aa10dd.png
[70 10]: /images/20220514/99161273d43d4bb1bda6183089e19ad6.png
[70 11]: /images/20220514/6466181d6e1f4cdc98ba5c56e8d13aff.png
[70 12]: /images/20220514/0616a02e3e8c49f689c59c2f25b056a7.png
[70 13]: /images/20220514/2c4a9e6b05a14d8e9decec9688bea720.png
[70 14]: /images/20220514/28c62d3ffaf843ea91eafb40bc9bc474.png
[70 15]: /images/20220514/be92b312e0614546a889ca6bd3687e86.png
[70 16]: /images/20220514/e0a4dc2307fa49e5a3d405f0ec91dc77.png