7. 理解GC日志

1 前言

阅读GC日志是处理Java虚拟机内存问题的基础技能，它只是一些人为确定的规则，没有太多技术含量。每一种收集器的日志形式都是由它们自身的实现所决定的，换而言之，每个收集器的日志格式都可以不一样。但虚拟机设计者为了方便用户阅读，将各个收集器的日志都维持一定的共性。

2 打印 GC 日志

2.1 启动参数

JVM 默认是不打印 GC 日志的，如果要打印 GC 日志进行分析，需要在 JVM 的启动参数中增加 GC 日志相关的参数，启动参数为-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D://logs/gc.log，参数解释如下：

-XX:+PrintGC  打印最基本的回收信息
-XX:+PrintGCDetails 可以打印详细GC信息至控制台
-XX:+PrintGCDateStamps 可以记录GC发生的详细时间
-Xloggc:{目录.../gc.log} 可以把GC日志文件输出至指定目前下

2.2 生成 GC 日志文件

示例代码

import java.util.ArrayList;
import java.util.List;

/**
 * VM Args：-Xms20m -Xmx20m -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D://logs/gc.log
 *
 * @author ddpyjqtd
 */
public class HeapOOM {
    static class OOMObject {
    }

    public static void main(String[] args) {
        List<OOMObject> list = new ArrayList<OOMObject>();
        while (true) {
            list.add(new OOMObject());
        }
    }
}

设置启动参数-Xms20m -Xmx20m -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D://logs/gc.log。

在 jdk1.8 环境下运行代码后，在 D://logs 文件夹下（该文件夹需要事先创建好，不然不会生成 GC 日志文件，因为会报文件夹不存在）发现生成 gc.log 文件，该文件就是 GC 日志信息。

3 垃圾收集器日志详解

虽说各个收集器的日志都维持一定的共性，但每个垃圾收集器还是会有细微区别。

3.1 Parallel Scavenge + Parallel Old

3.1.1 GC 日志内容

打开上面生成的GC日志文件，内容如下：

Java HotSpot(TM) 64-Bit Server VM (25.91-b15) for windows-amd64 JRE (1.8.0_91-b15), built on May 20 2016 17:43:15 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16629580k(9454288k free), swap 19119948k(8779844k free)
CommandLine flags: -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
2020-03-19T20:40:46.867+0800: 0.107: [GC (Allocation Failure) [PSYoungGen: 5632K->488K(6144K)] 5632K->3193K(19968K), 0.0045750 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2020-03-19T20:40:46.873+0800: 0.113: [GC (Allocation Failure) [PSYoungGen: 6120K->488K(6144K)] 8825K->7928K(19968K), 0.0077140 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2020-03-19T20:40:46.884+0800: 0.124: [Full GC (Ergonomics) [PSYoungGen: 6120K->0K(6144K)] [ParOldGen: 10605K->12502K(13824K)] 16725K->12502K(19968K), [Metaspace: 3279K->3279K(1056768K)], 0.1660132 secs] [Times: user=0.58 sys=0.02, real=0.17 secs] 
2020-03-19T20:40:47.051+0800: 0.291: [Full GC (Ergonomics) [PSYoungGen: 4009K->2938K(6144K)] [ParOldGen: 12502K->13520K(13824K)] 16511K->16459K(19968K), [Metaspace: 3280K->3280K(1056768K)], 0.1478138 secs] [Times: user=0.95 sys=0.00, real=0.15 secs] 
2020-03-19T20:40:47.199+0800: 0.439: [Full GC (Allocation Failure) [PSYoungGen: 2938K->2938K(6144K)] [ParOldGen: 13520K->13502K(13824K)] 16459K->16440K(19968K), [Metaspace: 3280K->3280K(1056768K)], 0.1260075 secs] [Times: user=0.67 sys=0.05, real=0.13 secs] 
Heap
 PSYoungGen      total 6144K, used 3274K [0x00000000ff980000, 0x0000000100000000, 0x0000000100000000)
  eden space 5632K, 58% used [0x00000000ff980000,0x00000000ffcb2be8,0x00000000fff00000)
  from space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
  to   space 512K, 0% used [0x00000000fff00000,0x00000000fff00000,0x00000000fff80000)
 ParOldGen       total 13824K, used 13502K [0x00000000fec00000, 0x00000000ff980000, 0x00000000ff980000)
  object space 13824K, 97% used [0x00000000fec00000,0x00000000ff92f948,0x00000000ff980000)
 Metaspace       used 3311K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 363K, capacity 388K, committed 512K, reserved 1048576K

3.1.2 GC 日志分析

• 第1行显示当前运行环境基本信息。
• 第2行显示当前运行环境内存信息。
• 第3行中显示当前运行 JVM 使用的参数。

1. -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520表示启动堆内存与最大堆内存都是20M，与配置参数一致。
2. 末尾处发现-XX:+UseParallelGC ，在启动参数中我并没有配置该项内容，但 GC 日志信息显示使用了 Parallel 垃圾收集器，这代表着在 JDK1.8 的环境中默认使用的垃圾收集器是 Parallel Scavenge 与 Paralell Old 收集器。

• 第4-8行显示执行 GC 的具体情况。

1. 2020-03-19T20:40:46.867+0800: 0.107:表示在2020-03-19 20:40:46.867时间点发生了GC ，从JVM启动时间点开始计划，经过了0.107秒后发生的GC。
2. [GC 表示停顿的类型，表示发生了普通GC，需要注意的是这个不代表是在新生代发生了GC。[FULL GC 表示发生了FULL GC。
3. (Allocation Failure) 表示内存分配失败导致发生的GC。(Ergonomics)说明对于注重吞吐量的收集器来说，在某个generation被过渡使用之前，GC ergonomics就会启动一次GC
4. [PSYoungGen: 5632K->488K(6144K)] 表示 发生在新生代中，GC前在该内存区域（新生代）已使用内存大小 --> GC后该内存区域（老年代）已使用内存大小（该内存区域（新生代）内存总大小）。
5. 5632K->3193K(19968K), 0.0045750 secs] 表示GC前已使用JAVA堆内存大小–> GC后已使用Java堆内存大小（Java堆内存总大小）。 0.0045750 secs表示该次GC执行时长为0.0045750秒。
6. [Times: user=0.00 sys=0.00, real=0.00 secs] 表示三个执行时长，单位是秒。user/sys/real 分别表示用户态消耗的CPU时间、内核态消耗的CPU时间、操作从开始到结束所经过的墙钟时间。

• 第9-17行表示Java运行时数据区域中各区域空间使用情况。

3.2 Serial + Serial Old

3.2.1 GC 日志内容

设置Serial 垃圾收集器，修改启动参数-Xms20m -Xmx20m -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D://logs/gc.log -XX:+UseSerialGC，再次运行得到GC日志文件内容如下：

Java HotSpot(TM) 64-Bit Server VM (25.91-b15) for windows-amd64 JRE (1.8.0_91-b15), built on May 20 2016 17:43:15 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16629580k(9225384k free), swap 19119948k(7898672k free)
CommandLine flags: -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseSerialGC 
2020-03-19T21:15:12.805+0800: 0.137: [GC (Allocation Failure) 2020-03-19T21:15:12.805+0800: 0.138: [DefNew: 5504K->639K(6144K), 0.0054107 secs] 5504K->3023K(19840K), 0.0055181 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2020-03-19T21:15:12.813+0800: 0.145: [GC (Allocation Failure) 2020-03-19T21:15:12.813+0800: 0.145: [DefNew: 6143K->640K(6144K), 0.0095007 secs] 8527K->7588K(19840K), 0.0095446 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2020-03-19T21:15:12.825+0800: 0.157: [GC (Allocation Failure) 2020-03-19T21:15:12.825+0800: 0.157: [DefNew: 6144K->640K(6144K), 0.0107355 secs] 13092K->13092K(19840K), 0.0107776 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2020-03-19T21:15:12.836+0800: 0.169: [GC (Allocation Failure) 2020-03-19T21:15:12.836+0800: 0.169: [DefNew: 6144K->6144K(6144K), 0.0000112 secs]2020-03-19T21:15:12.836+0800: 0.169: [Tenured: 12452K->13695K(13696K), 0.0255030 secs] 18596K->15077K(19840K), [Metaspace: 3280K->3280K(1056768K)], 0.0255599 secs] [Times: user=0.02 sys=0.00, real=0.03 secs] 
2020-03-19T21:15:12.862+0800: 0.195: [Full GC (Allocation Failure) 2020-03-19T21:15:12.862+0800: 0.195: [Tenured: 13695K->13695K(13696K), 0.0268477 secs] 17263K->17089K(19840K), [Metaspace: 3280K->3280K(1056768K)], 0.0268885 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 
2020-03-19T21:15:12.889+0800: 0.222: [Full GC (Allocation Failure) 2020-03-19T21:15:12.889+0800: 0.222: [Tenured: 13695K->13696K(13696K), 0.0307711 secs] 17089K->16440K(19840K), [Metaspace: 3280K->3280K(1056768K)], 0.0308158 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 
Heap
 def new generation   total 6144K, used 2892K [0x00000000fec00000, 0x00000000ff2a0000, 0x00000000ff2a0000)
  eden space 5504K,  52% used [0x00000000fec00000, 0x00000000feed3160, 0x00000000ff160000)
  from space 640K,   0% used [0x00000000ff200000, 0x00000000ff200000, 0x00000000ff2a0000)
  to   space 640K,   0% used [0x00000000ff160000, 0x00000000ff160000, 0x00000000ff200000)
 tenured generation   total 13696K, used 13696K [0x00000000ff2a0000, 0x0000000100000000, 0x0000000100000000)
   the space 13696K, 100% used [0x00000000ff2a0000, 0x0000000100000000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3311K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 363K, capacity 388K, committed 512K, reserved 1048576K

3.2.2 GC 日志分析

• 大部分内容与上面分析一致
• 第4-9行显示执行 GC 的具体情况。

1. [DefNew、[Tenured 表示GC发生的区域，DefNew表示发生在新生代，Tenured 表示发生在老年代。该名称与垃圾收集器有关。
2. [Metaspace: 表示元空间发生了GC。

3.3 ParNew + CMS [+ Serial Old]

3.3.1 GC 日志内容

设置Serial 垃圾收集器，修改启动参数-Xms20m -Xmx20m -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D://logs/gc.log -XX:+UseConcMarkSweepGC，再次运行得到GC日志文件内容如下：

Java HotSpot(TM) 64-Bit Server VM (25.91-b15) for windows-amd64 JRE (1.8.0_91-b15), built on May 20 2016 17:43:15 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16629580k(9499140k free), swap 19119948k(7866528k free)
CommandLine flags: -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=6991872 -XX:MaxTenuringThreshold=6 -XX:NewSize=6991872 -XX:OldPLABSize=16 -XX:OldSize=13979648 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
2020-03-19T21:24:57.795+0800: 0.116: [GC (Allocation Failure) 2020-03-19T21:24:57.795+0800: 0.116: [ParNew: 5504K->640K(6144K), 0.0241733 secs] 5504K->3925K(19840K), 0.0243051 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
2020-03-19T21:24:57.821+0800: 0.143: [GC (Allocation Failure) 2020-03-19T21:24:57.822+0800: 0.143: [ParNew: 6144K->640K(6144K), 0.0112307 secs] 9429K->9754K(19840K), 0.0112838 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2020-03-19T21:24:57.833+0800: 0.155: [GC (CMS Initial Mark) [1 CMS-initial-mark: 9114K(13696K)] 10077K(19840K), 0.0005840 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2020-03-19T21:24:57.834+0800: 0.155: [CMS-concurrent-mark-start]
2020-03-19T21:24:57.835+0800: 0.157: [GC (Allocation Failure) 2020-03-19T21:24:57.835+0800: 0.157: [ParNew: 6144K->6144K(6144K), 0.0000187 secs]2020-03-19T21:24:57.835+0800: 0.157: [CMS2020-03-19T21:24:57.851+0800: 0.173: [CMS-concurrent-mark: 0.016/0.017 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
 (concurrent mode failure): 9114K->13695K(13696K), 0.0468245 secs] 15258K->14707K(19840K), [Metaspace: 3280K->3280K(1056768K)], 0.0468962 secs] [Times: user=0.06 sys=0.00, real=0.05 secs] 
2020-03-19T21:24:57.890+0800: 0.211: [Full GC (Allocation Failure) 2020-03-19T21:24:57.890+0800: 0.211: [CMS: 13695K->13428K(13696K), 0.0331500 secs] 19839K->18342K(19840K), [Metaspace: 3280K->3280K(1056768K)], 0.0331971 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 
2020-03-19T21:24:57.923+0800: 0.244: [GC (CMS Initial Mark) [1 CMS-initial-mark: 13428K(13696K)] 18769K(19840K), 0.0080871 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2020-03-19T21:24:57.931+0800: 0.253: [CMS-concurrent-mark-start]
2020-03-19T21:24:57.942+0800: 0.263: [Full GC (Allocation Failure) 2020-03-19T21:24:57.942+0800: 0.263: [CMS2020-03-19T21:24:57.946+0800: 0.267: [CMS-concurrent-mark: 0.011/0.015 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
 (concurrent mode failure): 13695K->13695K(13696K), 0.0447719 secs] 19839K->19839K(19840K), [Metaspace: 3280K->3280K(1056768K)], 0.0448242 secs] [Times: user=0.08 sys=0.00, real=0.04 secs] 
2020-03-19T21:24:57.987+0800: 0.308: [Full GC (Allocation Failure) 2020-03-19T21:24:57.987+0800: 0.308: [CMS: 13695K->13677K(13696K), 0.0333543 secs] 19839K->19821K(19840K), [Metaspace: 3280K->3280K(1056768K)], 0.0333978 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 
2020-03-19T21:24:58.020+0800: 0.341: [GC (CMS Initial Mark) [1 CMS-initial-mark: 13680K(13696K)] 19824K(19840K), 0.0081375 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2020-03-19T21:24:58.028+0800: 0.350: [CMS-concurrent-mark-start]
2020-03-19T21:24:58.028+0800: 0.350: [Full GC (Allocation Failure) 2020-03-19T21:24:58.028+0800: 0.350: [CMS2020-03-19T21:24:58.041+0800: 0.363: [CMS-concurrent-mark: 0.012/0.014 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
 (concurrent mode failure): 13696K->13696K(13696K), 0.0777068 secs] 19839K->19839K(19840K), [Metaspace: 3280K->3280K(1056768K)], 0.0777635 secs] [Times: user=0.08 sys=0.00, real=0.08 secs] 
2020-03-19T21:24:58.106+0800: 0.428: [Full GC (Allocation Failure) 2020-03-19T21:24:58.106+0800: 0.428: [CMS: 13696K->13696K(13696K), 0.0358141 secs] 19839K->19839K(19840K), [Metaspace: 3280K->3280K(1056768K)], 0.0358535 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] 
2020-03-19T21:24:58.214+0800: 0.536: [Full GC (Allocation Failure) 2020-03-19T21:24:58.214+0800: 0.536: [CMS: 13696K->618K(13696K), 0.0082110 secs] 19839K->618K(19840K), [Metaspace: 3280K->3280K(1056768K)], 0.0082622 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Heap
 par new generation   total 6144K, used 189K [0x00000000fec00000, 0x00000000ff2a0000, 0x00000000ff2a0000)
  eden space 5504K,   3% used [0x00000000fec00000, 0x00000000fec2f688, 0x00000000ff160000)
  from space 640K,   0% used [0x00000000ff160000, 0x00000000ff160000, 0x00000000ff200000)
  to   space 640K,   0% used [0x00000000ff200000, 0x00000000ff200000, 0x00000000ff2a0000)
 concurrent mark-sweep generation total 13696K, used 618K [0x00000000ff2a0000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3311K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 363K, capacity 388K, committed 512K, reserved 1048576K

3.3.2 GC 日志分析

• 大部分内容与上面分析一致
• 第3行中显示当前运行 JVM 使用的参数。

1. -XX:MaxNewSize=6991872表示JVM堆区域新生代内存的最大可分配大小为6.67M，是20M的1/3，表示未设置新生代内存时最大可分配空间为JVM总内存空间的1/3。
2. -XX:NewSize=6991872表示JVM堆区域中新生代初始内存的大小为6.67M，是JVM总内存空间的1/3，表示未设置新生代内存时新生代初始内存分配空间为JVM总内存空间的1/3。
3. -XX:OldSize=13979648表示JVM堆区域中老生代初始内存的大小为13.3M，是JVM总内存空间的2/3，表示未设置老生代内存时老生代初始内存分配空间为JVM总内存空间的2/3。
4. -XX:MaxTenuringThreshold=6表示年龄阈值，表示对象复制到指定次数后会从新生代移动到老年代中。对于 CMS 收集器，他的默认年龄阈值是6。 补充说明：G1与Parallel Scavenge中默认值都是15。

• 第4-21行显示执行 GC 的具体情况。

1. (CMS Initial Mark) 表示 CMS 的初始标记。
2. CMS-concurrent-mark-start表示 CMS 的并发标记开始。
3. (concurrent mode failure)CMS垃圾收集器特有的错误，CMS的垃圾清理和引用线程是并行进行的，如果在并行清理的过程中老年代的空间不足以容纳应用产生的垃圾，则会抛出“concurrent mode failure”。出现此现象的原因主要有3个：1.CMS触发太晚;2.空间碎片太多;3.垃圾产生速度超过清理速度。
4. [ParNew表示新生代使用的是 ParNew 垃圾收集器。
5. CMS-concurrent-mark表示 CMS 的并发标记。

3.4 G1(Garbage-First)

篇幅过长，G1 垃圾收集日志单独篇章进行说明。