本文记录了一次项目 GC 的优化总结。包括项目出现 GC 的原因分析和解决方案。
项目 GC 优化总结
0. 背景1. 修改 jvm 启动参数2. 使用 JProfiler 分析堆转储文件3. 持续优化4. 代码分析5. 优化之后的结果- JVM 堆內存使用情況- GC 暂停耗时
0. 背景
监控系统上线之后，发现项目每个小时会进行一次 System.gc()，平均每次 System.gc() 花费的时间为 4s 左右。发生 System.gc() 时会暂停整个进程 (Stop-The-World)，这对于系统的响应速度会产生极大的影响。
1. 修改 jvm 启动参数
通过修改 jvm 启动参数，让系统在发生 Full GC 时生成堆转储文件。
java -Xmx2G -Xms2G -XX:+HeapDumpOnOutOfMemoryError -XX:+HeapDumpBeforeFullGC -XX:+HeapDumpAfterFullGC -XX:HeapDumpPath=/data/coredump/foo.dump -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:/data/logs/foo/gc.log -jar foo.jar
| jvm 参数 | 含义 |
|---|---|
| -XX:+HeapDumpOnOutOfMemoryError | 在发生 OutOfMemory 错误时生成堆转储文件 |
| -XX:+HeapDumpBeforeFullGC | 在发生 FullGc 之前生成堆转储文件 |
| -XX:+HeapDumpAfterFullGC | 在发生 FullGc 之后生成堆转储文件 |
| -XX:HeapDumpPath=/data/coredump/foo.dump | 指定堆转储文件保存位置 |
| -verbose:gc | 在控制台输出 GC 情况 |
| -XX:+PrintGCDetails | 在控制台输出详细的 GC 情况 |
| -XX:+PrintGCTimeStamps | 打印 GC 发生时的时间戳 |
| -Xloggc:/data/logs/foo/gc.log | 指定 GC 日志保存的位置 |
2. 使用 JProfiler 分析堆转储文件
使用 JMeter 压测项目的接口，在系统发生 Full GC 时会生成堆转储文件。我们用 JProfiler 打开生成的 dump 文件：
点击 [ Biggest Objects ]，发现 com.lmax.disruptor.RingBuffer 对象占了 53% 的空间
选中这个具体的类，点击 [Show In Graph]，可以在 Graph 选项卡中查看它关联的对象：
发现关联的对象都是 Log4jEventWrapper。
分析：因为异步日志过多导致的堆内存过大
优化：精简部分日志，只打印有用的日志
3. 持续优化
经过了第二步的优化之后，继续压测，导出堆转储文件继续分析
发现最大的对象变成了 com.ctrip.framework.apollo.spring.property.SpringValueRegistry 对象，占用了堆内存的 92% (1076MB) 的空间。
从名字可以推测出，这个可能和 Apollo 的配置项有关。
右键[Use Selected Objects] -> 选择 [References]
发现对应的 LinkedListMultimap 中保存的都是 key 为 dc.security.transaction.start 的对象。
4. 代码分析
通过全局搜索，发现代码中有两处调用 dc.security.transaction.start 的地方，都是通过 @Value 注解来读取 Apollo 上的配置。
public class DataController {
@Value("${dc.security.transaction.start:1568044800000}")
private long securityStart;
...
}
public class DispatchServiceImpl implements DispatchService {
@Value("${dc.security.transaction.start:1568044800000}")
private long securityStart;
...
}
分析：@Value 注解的对象没有释放，项目每次请求都会产生新的 LinkedListMultimapNode中保存的都是key为∗∗dc.security.transaction.start∗∗的对象。(https://seven−blog−2019.oss−cn−beijing.aliyuncs.com/references)¨通过全局搜索，发现代码中有两处调用∗∗dc.security.transaction.start∗∗的地方，都是通过∗∗@Value∗∗注解来读取Apollo上的配置。分析：@Value注解的对象没有释放，项目每次请求都会产生新的LinkedListMultimapNode对象
优化：此部分逻辑用于控制指定时间点之后打印加密的日志，时间点已经过去了(2019-09-10 00:00:00)，此部分逻辑不需要了。因此删除这部分逻辑。
5. 优化之后的结果
经过了以上的优化，上线之后，发现效果明显。
- JVM 堆內存使用情況
JVM 堆内存使用量从平均 5G 左右降低到了平均 3G。
- GC 暂停耗时
GC 暂停耗时从平均 4s 降低到了平均 500 ms。
TODO：500ms 的 GC 暂停时间还有继续优化的空间，可以持续进行优化。
