JVM系统优化实践(12):GC日志分析

时间:2022-03-03 01:06:12

您好,我是湘王,这是我的51CTO博客,欢迎您来,欢迎您再来~




了解了基本的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状态为:

JVM系统优化实践(12):GC日志分析


而执行完array1时,已堆满垃圾:

JVM系统优化实践(12):GC日志分析


执行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内存状况:

JVM系统优化实践(12):GC日志分析


GC后JVM内存状况:

7291K->608K(19456K)

JVM系统优化实践(12):GC日志分析


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

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];

}

JVM系统优化实践(12):GC日志分析



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

JVM系统优化实践(12):GC日志分析


代码执行完成后:

JVM系统优化实践(12):GC日志分析


查看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。

JVM系统优化实践(12):GC日志分析


查看GC日志:

JVM系统优化实践(12):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内存状态:

JVM系统优化实践(12):GC日志分析


执行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中的剩余对象全部进入老年代。

JVM系统优化实践(12):GC日志分析

上面的GC日志说明:

Eden区使用了26%,正是array4对象;

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


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




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