JVM频繁GC分析

本文记录一次频繁GC的分析

问题

查看项目日志发现GC频繁，几乎几秒钟一次

查看GC日志

[GC (Allocation Failure) [PSYoungGen: 6816K->320K(8192K)] 82693K->76229K(187904K), 0.0032930 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [PSYoungGen: 6464K->224K(8192K)] 82373K->76165K(187904K), 0.0067897 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC (Allocation Failure) [PSYoungGen: 6368K->192K(8192K)] 82309K->76149K(187904K), 0.0052315 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC (Allocation Failure) [PSYoungGen: 6336K->1152K(8192K)] 82293K->77117K(187904K), 0.0026567 secs] [Times: user=0.05 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [PSYoungGen: 7296K->1184K(8192K)] 83261K->77157K(187904K), 0.0049316 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC (Allocation Failure) [PSYoungGen: 7202K->1056K(8192K)] 83175K->77037K(187904K), 0.0053079 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC (Allocation Failure) [PSYoungGen: 7181K->912K(8192K)] 83162K->76901K(187904K), 0.0045949 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [PSYoungGen: 7056K->544K(8192K)] 83045K->76557K(187904K), 0.0066989 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

• GC日志打印YGC日志非常频繁，几秒钟一次。 PSYoungGen 是使用Parallel Scavenage垃圾收集器的年轻代

• 从日志上可以看到 7056K->544K(8192K) 年轻代总大小非常小只有8M，这就是产生频繁YGC的原因

• 当new了一个新对象，Young区内存不够分配时，就会触发一次YGC。

那么为什么Young区会这么小呢？

Jstat查看GC情况

通过 jstat -gc 2668 10000 7 查看GC情况

$   jstat -gc 2668 10000 7
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
2048.0 1024.0  0.0   704.0   5632.0   5504.2   179712.0   80893.3   55552.0 53214.6 6912.0 6470.5   9573   69.553   6      0.593   70.146
2048.0 2048.0  0.0   1184.1  5120.0   911.5    179712.0   80973.3   55552.0 53214.6 6912.0 6470.5   9577   69.573   6      0.593   70.167
2048.0 2048.0 1024.0  0.0    5120.0   1978.0   179712.0   81005.3   55552.0 53214.6 6912.0 6470.5   9580   69.596   6      0.593   70.189
2048.0 2048.0  0.0   224.0   5120.0   3156.5   179712.0   81069.3   55552.0 53214.6 6912.0 6470.5   9583   69.614   6      0.593   70.207
2048.0 2048.0 1216.1  0.0    5120.0   4161.0   179712.0   81125.3   55552.0 53214.6 6912.0 6470.5   9586   69.632   6      0.593   70.225
2048.0 2560.0 1984.0  0.0    4608.0   2132.9   179712.0   81213.3   55552.0 53214.6 6912.0 6470.5   9590   69.660   6      0.593   70.253
3584.0 3584.0 2144.0  0.0    4096.0   2305.9   179712.0   81381.3   55552.0 53214.6 6912.0 6470.5   9594   69.683   6      0.593   70.276

上述结果列含义如下：

EC 表示eden区大小
EU 表示eden区已使用空间大小
S0C 表示 Survival 0 区容量
S1C 表示 Survival 1 区容量
S0U 表示 Survival 0 区已使用空间大小
S1U 表示 Survival 1 区已使用空间大小
相关参数看考文档（java8）：https://docs.oracle.com/javase/8/docs/technotes/tools/windows/jstat.html#BEHHGFAE

从上面可以看到，eden区、S0区和S1区大小一直在变化而且并不一定相等，那么为什么堆区大小一直在变化呢？

查了一下发现jvm有个参数UseAdaptiveSizePolicy开启了，该参数是默认开启的，

查看jvm参数：

$ java -XX:+PrintFlagsFinal -version | grep UseAdaptiveSizePolicy
     bool UseAdaptiveSizePolicy                     = true                                {product}

结论

那么可以确定原因基本上是jvm由于开启了UseAdaptiveSizePolicy参数，jvm自动调整堆大小，由于Young区被调整太小导致频繁发生YGC，我们可以通过调整启动参数来避免这种情况。

重新设置启动参数

-XX:+PrintGCDetails -XX:-UseAdaptiveSizePolicy -XX:SurvivorRatio=8 -Xmn100M 

-XX:+PrintGCDetails 启用日志
-XX:-UseAdaptiveSizePolicy 关闭自动跳转堆区大小
-XX:SurvivorRatio=8 设置eden区和survivor区大小比8
-Xmn100M 置Young区大小

参考：

https://docs.oracle.com/javase/8/docs/technotes/tools/windows/jstat.html#BEHHGFAE