快速入门Java GC日志分析

更新时间:
复制 MD 格式

本文演示如何通过ATPJava GC日志分析,寻找应用出现响应超时的原因。

1. 生成数据源,上传到ATP

假设某应用对接口的响应时间要求较高,超过1秒就判定为超时。某天发现线上接口时不时出现超时,怀疑是GC暂停导致的。

这时,我们可以找到应用的GC日志,并将它上传到ATP,然后开始分析(具体操作参见开始使用ATP)。

2. 使用ATP GC日志分析

在分析结果界面中,通常我们会先查看GC类型,GC线程数,日志覆盖的时间段等信息,排除误操作,确认该文件和我们要分析的应用匹配。

接下来可以调整一下【分析配置】,选择出现超时问题的时段。由于对暂停时间要求较高,可以把长暂停时间阈值设置到200ms。

其他参数保持默认值:Young GC 间隔阈值(ms)1000,Old GC 间隔阈值(ms)15000,Full GC 间隔阈值(ms)60000。设置完成后单击确定

接下来看一下【问题诊断】视图,在这里ATP会根据日志的情况自动帮发现较为严重的问题并给出部分调优建议。发现大约在4点左右有一次Final Remark的时间较长。

ATP给出的调优建议包括:若Rescan时间长,可添加-XX:+CMSScavengeBeforeRemark参数;若Reference Processing时间长,可开启-XX:+ParallelRefProcEnabled多线程处理(JDK 11后默认开启),或排查Weak/Soft/Phantom Reference;若Class Unloading时间长,需优化代码减少class loader数量。

看一下【暂停信息】视图,能确认最长的一次暂停来自一次Final Remark导致的暂停,长达442ms,可能是导致超时的元凶。image

用户可以在【日志详情】视图中,通过在搜索条件中设置暂停时间范围来筛选并找到这次Final Remark事件。在事件详情中,可以看到该次Final Remark的暂停时间主要由RescanClass Unloading两个阶段组成,据此可针对性地进行调优。

然后再看一下【内存统计】视图,发现每次Old gc后内存使用率都较低,对象创建和晋升速度都较低,不需要做额外的堆分析来排查内存问题。

3. 结论

根据以上收集到的信息,我们可以大致确认应用出现超时的原因是CMS Final Remark,需要优化其暂停时间,可以考虑通过优化JVM参数或者升级到G1 GC来解决。