详细解析一次JVM GC长暂停的排查过程

背景

在高并发下，Java程序的GC问题属于很典型的一类问题，带来的影响往往会被进一步放大。不管是「GC频率过快」还是「GC耗时太长」，由于GC期间都存在Stop The World问题，因此很容易导致服务超时，引发性能问题。

事情最初是线上某应用垃圾收集出现Full GC异常的现象，应用中个别实例Full GC时间特别长，持续时间约为15~30秒，平均每2周左右触发一次；







JVM参数配置“-Xms2048M –Xmx2048M –Xmn1024M –XX:MaxPermSize=512M”





排查过程

Ø 分析GC 日志

GC 日志它记录了每一次的 GC 的执行时间和执行结果，通过分析 GC 日志可以调优堆设置和 GC 设置，或者改进应用程序的对象分配模式。

这里Full GC的reason是Ergonomics，是因为开启了UseAdaptiveSizePolicy，jvm自己进行自适应调整引发的Full GC。

这份日志主要体现GC前后的变化，目前为止看不出个所以然来。





开启GC日志，需要添加如下 JVM 启动参数：

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/export/log/risk_pillar/gc.log

常见的 Young GC、Full GC 日志含义如下：





Ø 进一步查看服务器性能指标

获取到了GC耗时的时间后，通过监控平台获取到各个监控项，开始排查这个时点有异常的指标，最终分析发现，在5.06分左右（GC的时点），CPU占用显著提升，而SWAP出现了释放资源、memory资源增长出现拐点的情况（详见下图红色框，橙色框中的变化是因修改配置导致，后面会介绍，暂且可忽略）





JVM用到了swap？是因为GC导致的CPU突然飙升，并且释放了swap交换区这部分内存到memory？

为了验证JVM是否用到swap，我们通过检查proc下的进程内存资源占用情况

| for i in (cd/proc;ls∣grep"[0−9]"∣awk′( cd /proc;ls |grep "^[0-9]"|awk ' (cd/proc;ls∣grep"[0−9]"∣awk′0 >100') ;do awk '/Swap:/{a=a+2}END{print '"i"',a/1024"M"}'