Java GC日志分析 - GC暂停时间长

通过Java GC日志分析,帮助用户从CMS GC升级到G1 GC,解决升级过程中的各种问题。

用户诉求

某日接到业务同学的反馈如下:

  1. 业务运行过程中经常出现超长的暂停时 间,导致健康检查失败,引发问题。

  2. 应用本身是做离线数据处理,对时延要求不是很高,能保证大部分暂停在1200毫秒以下不要出现超长的暂停即可,更加看重应用的吞吐。

  3. 应用当前使用的是CMS GC,用户希望顺应技术发展趋势,升级到G1 GC,并一并解决上述问题。

GC日志分析

首先看一下原本使用CMS时问题有多严重,文件上传后先调整一下分析配置:

image

看问题诊断,发现有很多Full GC、Final Remark和Young GC的暂停时间都会超过1200ms。

image

再看一下暂停视图,发现有时超时非常多。

image

用户修改了JVM启动参数,从CMS GC升级到G1 GC,运行了一段时间后重新上传GC日志进行分析,看问题诊断,暂停信息和GC阶段三个部分:

image

image

image

发现升级到G1 GC后可以看到应用的暂停时间基本满足要求了,但是由于G1默认会试图把应用暂停尽量控制在200ms以下,而当前应用的暂停整体偏长,导致G1试图把年轻代压缩得特别小来控制暂停时间,导致GC变得较为频繁,引起应用整体的吞吐下降(应用吞吐主要看的是”GC暂停时间占比“指标,从2.38%升到了3.87%)。

为了降低Young GC的频率增大年轻代大小,应用按照建议增加了以下JVM参数进行调优:

-XX:MaxGCPauseMillis=400 -XX:+UnlockExperimentalVMOptions -XX:G1NewSizePercent=40

运行一段时间后,发现虽然能解决GC频繁的问题,但是由于年轻代大小的最小值被设的太高,影响了G1 GC自动调节能力,导致了新的Full GC和To-space Exhausted,引起超长暂停。

image

image

再次进行JVM参数调优:

-XX:G1NewSizePercent=20 -XX:-XX:InitiatingHeapOccupancyPercent=40

新的参数运行一段时间后没有再发现新的问题,至此用户G1 GC升级完成。用户在Java GC日志分析工具的辅助下,通过JVM参数调优,在保持应用吞吐影响不大的情况下解决了时延问题,整体效果满意。