JVM系统优化实践（12）：GC日志分析

您好，我是湘王，这是我的CSDN博客，欢迎您来，欢迎您再来～

---

了解了基本的G1垃圾回收机制以后，就可以结合实际日志分析一下它的日志内容了，以后再遇到问题自己也能看懂。

首先要说明一下实验环境：

1、预先设置的JVM参数：

-XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:NewSize=10485760 -XX:MaxNewSize=10485760 -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=10485760 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC

2、增加GC日志选项

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/home/work/logs/gc.log

3、操作系统和JDK环境（环境不同，结果可能不同）

Windows 10 × 64位企业版（15063）

JDK1.8_202_build-b08

示例的Java代码：

public static void main(String[] args) {

byte[] array1 = new byte[2 * 1024 * 1024];

array1 = new byte[2 * 1024 * 1024];

array1 = new byte[2 * 1024 * 1024];

array1 = null;

byte[] array2 = new byte[4 * 1024 * 1024];

}

这段代码在作用上就是个垃圾，实际开发的时候估计没谁会这么写，但用来分析GC内部的状态变化却是很好的例子。

执行第一行后，JVM状态为：

 

而执行完array1时，已堆满垃圾：

 

执行array2时，创建对象4M：byte[] array2 = new byte[4 * 1024 * 1024];

在已有3 × 2M对象情况下，eden空间不足，触发Young GC，可以看到日志内容：

1、CommandLine flags……打印出本次程序运行使用的JVM参数；

2、xxxx-xx-xxT22:16:12.896+0800: 0.107 [GC (Allocation Failure)……]表明在系统运行0.107秒之后发生了一次GC；

3、ParNew: 7291K->608K(9216K), 0.0008194 secs表明一次年轻代GC，GC前使用了7291K，GC后还有608K对象存活，GC后年轻代可用空间9216K，耗费0.0008194秒；

4、7291K->608K(19456K)表明整个JVM堆内存可用空间19456K，年轻代使用了7291K + 老年代10M，GC前整个JVM堆使用了7291K，GC后使用了608K；

5、Times: user=0.00 sys=0.00, real=0.00 secs表明本次GC消耗的时间，毫秒为单位。

GC前JVM内存状况：

 

GC后JVM内存状况：

7291K->608K(19456K)

 

再看看通过动态年龄判定进入老年代是怎么运行的。

1、相关JVM参数：

-XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:NewSize=10485760 -XX:MaxNewSize=10485760 -XX:MaxTenuringThreshold=15 -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=10485760 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/home/work/logs/gc.log

2、Java示例代码：

public static void main(String[] args) {

byte[] array1 = new byte[2 * 1024 * 1024];

array1 = new byte[2 * 1024 * 1024];

array1 = new byte[2 * 1024 * 1024];

array1 = null;

byte[] array2 = new byte[128 * 1024];

byte[] array3 = new byte[2 * 1024 * 1024];

}

 

代码执行中创造了3 × 2M的数组，JVM状态为：

 

代码执行完成后：

 

查看GC日志可知：

第一次GC后有608K对象存活，这一次有750K对象存活；

750 - 608 ≈ 128K（刚好为array2大小，就是存活的array2）

【ParNew: 7586K->750K(9216K), 0.0008034 secs】表明

1、GC前：3 × 2M + 128K + 其他对象 = 7586K；

2、GC后：存活对象128K ≈ 750K - 608K，年轻代可用空间9216K。

 

查看GC日志：

 

Eden区使用了26%，正是array3对象；

Survivor From使用了73% = 750K / 1024K，保存存活对象

此时Survivor From：

1、存活对象年龄：1岁

2、存活对象大小：＞Survivor × 50%

继续接下来完善代码，看看还会发生什么。

public static void main(String[] args) {

byte[] array1 = new byte[2 * 1024 * 1024];

array1 = new byte[2 * 1024 * 1024];

array1 = new byte[2 * 1024 * 1024];

array1 = null;

byte[] array2 = new byte[128 * 1024];

byte[] array3 = new byte[2 * 1024 * 1024];

array3 = new byte[2 * 1024 * 1024];

array3 = new byte[2 * 1024 * 1024];

array3 = new byte[128 * 1024];

array3 = null;

byte[] array4 = new byte[2 * 1024 * 1024];

}

执行array4前，JVM内存状态：

 

执行array4后，触发Young GC：

1、第一次：ParNew: 7583K->797K(9216K), 0.0005995 secs

2、第二次：ParNew: 7100K->0K(9216K), 0.0029498 secs

3、存活的128K对象 + 原来的750K ＞ Survivor × 50%

4、再次触发Young GC

按照动态年龄规则：年龄1 + 年龄2 + … … + 年龄n ＞ Survivor × 50%

因此array2和Survivor中的剩余对象全部进入老年代。

上面的GC日志说明：

 

Eden区使用了26%，正是array4对象；

触发了动态年龄规则，S0、S1已经空了，而老年代使用了739K。

可以通过代码模拟对象年龄在15岁之后才进入老年代，自己测试一下，做一个小练习，然后对照GC日志看看结果是否如预期那样。

---

感谢您的大驾光临！咨询技术、产品、运营和管理相关问题，请关注后留言。欢迎骚扰，不胜荣幸～