JVM GC 日志详解

本文采用的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)
复制代码

1、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]
复制代码

一、GC 表示是一次YGC（Young GC）

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

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

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

五、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]
复制代码

一、GC 表示是一次YGC（Young GC）

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

三、PSYoungGen 表示年轻代大小

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

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

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

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

八、 0.0039189 secs 表示此次GC总计所用的时间

九、[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

打印日志以下：

{Heap before GC invocations=1 (full 0):
 PSYoungGen      total 57344K, used 49152K [0x00000000fc000000, 0x0000000100000000, 0x0000000100000000)
  eden space 49152K, 100% used [0x00000000fc000000,0x00000000ff000000,0x00000000ff000000)
  from space 8192K, 0% used [0x00000000ff800000,0x00000000ff800000,0x0000000100000000)
  to   space 8192K, 0% used [0x00000000ff000000,0x00000000ff000000,0x00000000ff800000)
 ParOldGen       total 196608K, used 0K [0x00000000f0000000, 0x00000000fc000000, 0x00000000fc000000)
  object space 196608K, 0% used [0x00000000f0000000,0x00000000f0000000,0x00000000fc000000)
 Metaspace       used 7901K, capacity 8264K, committed 8448K, reserved 1056768K
  class space    used 888K, capacity 986K, committed 1024K, reserved 1048576K
[GC (Allocation Failure)  49152K->2416K(253952K), 0.0030218 secs]
Heap after GC invocations=1 (full 0):
 PSYoungGen      total 57344K, used 2400K [0x00000000fc000000, 0x0000000100000000, 0x0000000100000000)
  eden space 49152K, 0% used [0x00000000fc000000,0x00000000fc000000,0x00000000ff000000)
  from space 8192K, 29% used [0x00000000ff000000,0x00000000ff258020,0x00000000ff800000)
  to   space 8192K, 0% used [0x00000000ff800000,0x00000000ff800000,0x0000000100000000)
 ParOldGen       total 196608K, used 16K [0x00000000f0000000, 0x00000000fc000000, 0x00000000fc000000)
  object space 196608K, 0% used [0x00000000f0000000,0x00000000f0004000,0x00000000fc000000)
 Metaspace       used 7901K, capacity 8264K, committed 8448K, reserved 1056768K
  class space    used 888K, capacity 986K, committed 1024K, reserved 1048576K
}
复制代码

由此能够看出在，打印以下日志先后

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

详细打印出了日志信息

invocations 表示GC的次数，每次GC增长一次，每次GC先后的invocations相等

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

二、{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 相关）

2、CMS GC日志详细分析

[GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.558/5.093 secs] [Times: user=0.57 sys=0.00, real=5.09 secs] 
[GC (CMS Final Remark) [YG occupancy: 16817 K (29504 K)][Rescan (parallel) , 0.0021918 secs][weak refs processing, 0.0000245 secs][class unloading, 0.0044098 secs][scrub symbol table, 0.0029752 secs][scrub string table, 0.0006820 secs][1 CMS-remark: 19498K(32768K)] 36316K(62272K), 0.0104997 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
复制代码

CMS日志分为两个STW(stop the world)

分别是init remark（1） 与 remark（7）两个阶段。通常耗时比YGC长约10倍（我的经验）。

（1）、[GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs][Times: user=0.01 sys=0.00, real=0.01 secs]

会STO(Stop The World)，这时候的老年代容量为 32768K， 在使用到 19498K 时开始初始化标记。耗时短。

（2）、[CMS-concurrent-mark-start]

并发标记阶段开始

（3）、[CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

并发标记阶段花费时间。

（4）、[CMS-concurrent-preclean-start]

并发预清理阶段，也是与用户线程并发执行。虚拟机查找在执行并发标记阶段新进入老年代的对象(可能会有一些对象从新生代晋升到老年代， 或者有一些对象被分配到老年代)。经过从新扫描，减小下一个阶段”从新标记”的工做，由于下一个阶段会Stop The World。

（5）、[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

并发预清理阶段花费时间。

（6）、[CMS-concurrent-abortable-preclean-start] CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.558/5.093 secs][Times: user=0.57 sys=0.00, real=5.09 secs]

并发可停止预清理阶段，运行在并行预清理和从新标记之间，直到得到所指望的eden空间占用率。增长这个阶段是为了不在从新标记阶段后紧跟着发生一次垃圾清除

（7）、[GC (CMS Final Remark) [YG occupancy: 16817 K (29504 K)][Rescan (parallel) , 0.0021918 secs][weak refs processing, 0.0000245 secs][class unloading, 0.0044098 secs][scrub symbol table, 0.0029752 secs][scrub string table, 0.0006820 secs][1 CMS-remark: 19498K(32768K)] 36316K(62272K), 0.0104997 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

会STW(Stop The World)，收集阶段，这个阶段会标记老年代所有的存活对象，包括那些在并发标记阶段更改的或者新建立的引用对象

（8）、[CMS-concurrent-sweep-start]

并发清理阶段开始，与用户线程并发执行。

（9）、[CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

并发清理阶段结束，所用的时间。

（10）、[CMS-concurrent-reset-start]

开始并发重置。在这个阶段，与CMS相关数据结构被从新初始化，这样下一个周期能够正常进行。

（11）、[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

并发重置所用结束，所用的时间。

参考：

Geek-Yan: JVM 学习笔记(四) CMS GC日志详解

3、G1垃圾收集器

建议在堆内存大于6G以上来使用，这个是官网的推荐。

4、GC调优

设置JVM GC 性能的有以下参数

4.1 -Xmn

新生代大小官网推荐的大小是3/8, 若是设置过小，好比1/10会致使Minor GC 与Major GC次数增多。

4.2 -XX:MaxTenuringThreshold=n

其中n的大小为区间为[0,15],若是高于15，JDK7 会默认15，JDK 8会启动报错

5、常见问题

1 .并发模式失败（concurrent mode failure）

发生在CMS GC运行期间，详情参考：

JVM 调优 —— GC 长时间停顿问题及解决方法

GC的悲观策略

2. 提高失败（promotion failed）

发生在Minor GC期间

参考资料

1. 铁锚:快速解读GC日志
2. Geek-Yan: JVM 学习笔记(四) CMS GC日志详解