本文采用的JDK版本:

java version "1.8.0_144"
Java(TM) SE Runtime Environment (build 1.8.0_144-b01)
Java HotSpot(TM) 64-Bit Server VM (build 25.144-b01, mixed mode)

一、GC 日志参数

设置JVM GC格式日志的主要参数包括如下8个:

-XX:+PrintGC 输出简要GC日志 
-XX:+PrintGCDetails 输出详细GC日志 
-Xloggc:gc.log  输出GC日志到文件
-XX:+PrintGCTimeStamps 输出GC的时间戳(以JVM启动到当期的总时长的时间戳形式) 
-XX:+PrintGCDateStamps 输出GC的时间戳(以日期的形式,如 2013-05-04T21:53:59.234+0800) 
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-verbose:gc
-XX:+PrintReferenceGC 打印年轻代各个引用的数量以及时长

本文假设读者已经熟悉JVM 内存结构。

1.1 -XX:+PrintGC与-verbose:gc

如果想开启GC日志的信息,可以通过设置如下的参数任一参数:

-XX:+PrintGC
-XX:+PrintGCDetails 
-Xloggc:gc.log

如果只设置-XX:+PrintGC那么打印的日志如下所示:

[GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]

1、GC 表示是一次YGC(Young GC)

2、Allocation Failure 表示是失败的类型

3、68896K->5080K 表示年轻代从68896K降为5080K

4、256000K表示整个堆的大小

5、0.0041139 secs表示这次GC总计所用的时间

在JDK 8中,-verbose:gc-XX:+PrintGC一个别称,日志格式等价与:-XX:+PrintGC,。

不过在JDK 9中 -XX:+PrintGC被标记为deprecated

-verbose:gc是一个标准的选项, -XX:+PrintGC是一个实验的选项,建议使用-verbose:gc替代-XX:+PrintGC

参考:Difference between -XX:+PrintGC and -verbose:gc

1.2 -XX:+PrintGCDetails

[GC (Allocation Failure) [PSYoungGen: 53248K->2176K(59392K)] 58161K->7161K(256000K), 0.0039189 secs] [Times: user=0.02 sys=0.01, real=0.00 secs]

1、GC 表示是一次YGC(Young GC)

2、Allocation Failure 表示是失败的类型

3、PSYoungGen 表示年轻代大小

4、53248K->2176K 表示年轻代占用从53248K降为2176K

5、59392K表示年轻带的大小

6、58161K->7161K 表示整个堆占用从53248K降为2176K

7、256000K表示整个堆的大小

8、 0.0039189 secs 表示这次GC总计所用的时间

9、[Times: user=0.02 sys=0.01, real=0.00 secs] 分别表示,用户态占用时长,内核用时,真实用时。

时间保留两位小数,四舍五入。

1.3 -XX:+PrintGCTimeStamps

1.963: [GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]

如果加上-XX:+PrintGCTimeStamps那么日志仅仅比1.1介绍的最前面多了一个时间戳: 1.963, 表示从JVM启动到打印GC时刻用了1.963秒。

1.4 -XX:+PrintGCDateStamps

2019-03-05T16:56:15.108+0800: [GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]

如果加上-XX:+PrintGCDateStamps那么日志仅仅比1.1介绍的最前面多了一个日期时间: 2019-03-05T16:56:15.108+0800, 表示打印GC的时刻的时间是2019-03-05T16:56:15.108+0800。+0800表示是东8区。

1.5 -XX:+PrintHeapAtGC

这个参数开启后,

使用如下参数-verbose:gc -XX:+PrintHeapAtGC -Xmn64M -Xms256M -Xmx256M

打印日志如下:

由此可以看出在,打印如下日志前后

[GC (Allocation Failure)  49152K->2416K(253952K), 0.0030218 secs]

详细打印出了日志信息

invocations 表示GC的次数,每次GC增加一次,每次GC前后的invocations相等

1、Heap before GC invocations=1 表示是第1次GC调用之前的堆内存状况

2、{Heap before GC invocations=1 (full 0): 表示是第1次GC调用之后的堆内存状况

1.6 -Xloggc:gc.log

如果使用该参数-Xloggc则默认开启如下两个参数

-XX:+PrintGC -XX:+PrintGCTimeStamps

如果启动参数如下:-Xloggc:gc.log -Xmn64M -Xms256M -Xmx256M则日志格式如下所示

0.318: [GC (Allocation Failure) 49152K->2384K(253952K), 0.0038675 secs]

gc.log也可以指定绝对的路径。

在gc.log最前面还会默认打印系统的JDK版本与启动的参数

Java HotSpot(TM) 64-Bit Server VM (25.144-b01) for linux-amd64 JRE (1.8.0_144-b01), built on Jul 21 2017 21:57:33 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 16287104k(1657700k free), swap 16636924k(15826632k free)
CommandLine flags: -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=268435456 -XX:MaxNewSize=67108864 -XX:NewSize=67108864 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC

1.7 -XX:+PrintReferenceGC

此设置 -XX:+PrintReferenceGC可以打印出SoftReference,WeakReference,FinalReference,PhantomReference,JNI Weak Reference几种引用的数量,以及清理所用的时长,该参数在进行YGC调优时可以排上用场。

[GC (Allocation Failure) [SoftReference, 0 refs, 0.0000119 secs][WeakReference, 499 refs, 0.0000370 secs][FinalReference, 1045 refs, 0.0002313 secs][PhantomReference, 0 refs, 0 refs, 0.0000039 secs][JNI Weak Reference, 0.0000290 secs][PSYoungGen: 53456K->4880K(57344K)] 53496K->4928K(253952K), 0.0037199 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]

具体可以参考占小狼的一篇实战:一次 Young GC 的优化实践(FinalReference 相关)

参考现有项目的查看GC日志

-XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:${logPath}/java_gc.log \