GC日志是一个很重要的工具，它准确记录了每一次的GC的执行时间和执行结果，通过分析GC日志可以优化堆设置和GC设置，或者改进应用程序的对象分配模式。

GC日志参数

不同的垃圾收集器，输出的日志格式各不相同，但也有一些相同的特征。熟悉各个常用垃圾收集器的GC日志，是进行JVM调优的必备一步。解析GC日志，首先需要收集日志，常用的有以下JVM参数用来打印输出日志信息：

GC日志参数

如，使用如下参数启动：

-Xms28m
-Xmx28m
//开启记录GC日志详细信息（包括GC类型、各个操作使用的时间）,并且在程序运行结束打印出JVM的内存占用情况
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+UseGCLogFileRotation      开启滚动生成日志
-Xloggc:E:/logs/gc.log

常用垃圾收集器参数

GC日志分析

日志的含义

GC日志理解起来十分简单，因为日志本来就是要给开发人员看的，所以设计的很直观。

举个例子，我们来分别说明各个部分所代表的含义：

[GC (Allocation Failure) [PSYoungGen: 6146K->904K(9216K)] 6146K->5008K(19456K), 0.0038730
 secs] [Times: user=0.08 sys=0.00, real=0.00 secs]

将上面 GC 日志抽象为各个部分，然后我们再分别说明各个部分的含义：

[a(b)[c:d->e(f), g secs] h->i(j), k secs] [Times: user:l sys=m, real=n secs]

a: GC 或者是 Full GC
b: 用来说明发生这次 GC 的原因
c: 表示发生GC的区域，这里表示是新生代发生了GC，上面那个例子是因为在新生代中内存不够给新对象分配了，然后触发了 GC
d: GC 之前该区域已使用的容量
e: GC 之后该区域已使用的容量
f: 该内存区域的总容量
g: 表示该区域这次 GC 使用的时间
h: 表示 GC 前整个堆的已使用容量
i: 表示 GC 后整个堆的已使用容量
j: 表示 Java 堆的总容量
k: 表示 Java堆 这次 GC 使用的时间
l: 代表用户态消耗的 CPU 时间
m: 代表内核态消耗的 CPU 时间
n: 整个 GC 事件从开始到结束的墙钟时间（Wall Clock Time）

使用 ParNew + Serial Old 的组合进行内存回收

设置JVM参数：

-Xms20M -Xmx20M -Xmn10M -XX:+UseParNewGC -XX:+PrintGCDetails -XX:SurvivorRatio=8

测试代码：

public class TestGCLog01 {
    private static final int _1MB = 1024*1024;
    /**
     * VM参数：
     *  1.  -Xms20M -Xmx20M -Xmn10M -XX:+UseParNewGC -XX:+PrintGCDetails -XX:SurvivorRatio=8
     */
    public static void testAllocation() {
        byte[] allocation1, allocation2, allocation3, allocation4;
        allocation1 = new byte[2*_1MB];
        allocation2 = new byte[2*_1MB];
        allocation3 = new byte[2*_1MB];
        allocation4 = new byte[4*_1MB];
    }

    public static void main(String[] args) {
        testAllocation();
    }
}

打印结果：

[GC (Allocation Failure) [ParNew: 6146K->753K(9216K), 0.0065877 secs] 6146K->4849K(19456K),
0.0092108 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
Heap
par new generation total 9216K, used 7220K [0x00000000fec00000, 0x00000000ff600000,
0x00000000ff600000)
eden space 8192K, 78% used [0x00000000fec00000, 0x00000000ff250ea0, 0x00000000ff400000)
from space 1024K, 73% used [0x00000000ff500000, 0x00000000ff5bc488, 0x00000000ff600000)
to space 1024K, 0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
tenured generation total 10240K, used 4096K [0x00000000ff600000, 0x0000000100000000,
0x0000000100000000)
the space 10240K, 40% used [0x00000000ff600000, 0x00000000ffa00020, 0x00000000ffa00200,
0x0000000100000000)
Metaspace used 3362K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 369K, capacity 388K, committed 512K, reserved 1048576K
Java HotSpot(TM) 64-Bit Server VM warning: Using the ParNew young collector with the Serial old
collector is deprecated and will likely be removed in a future release

结果分析：

通过上面的GC日志我们可以看出一开始出现了 MinorGC, 引起GC的原因是内存分配失败，因为分配allocation的时候，Eden区已经没有足够的区域来分配了，所以发生来本次 MinorGC ，经过 MinorGC 之后新生代的已使用容量从6146K->753K，然而整个堆的内存总量却几乎没有减少，原因就是，由于发现新生代没有可以回收的对象，所以不得不使用内存担保将allocation1～3 三个对象提前转移到老年代。此时再在 Eden 区域为 allocation 分配 4MB 的空间，因此最后我们发现 Eden 区域占用了 4MB，老年代占用了 6MB。

使用 Parallel Scavenge + Parallel Old 的组合进行内存回收

设置参数：

-Xms20M -Xmx20M -Xmn10M -XX:+UseParallelGC -XX:+PrintGCDetails -XX:SurvivorRatio=8

测试代码：

public class TestGCLog02 {
    private static final int _1MB = 1024*1024;
    /**
     * VM参数：
     *  2. -Xms20M -Xmx20M -Xmn10M -XX:+UseParallelGC -XX:+UseParallelOldGC -XX:+PrintGCDetails -XX:SurvivorRatio=8
     */
    public static void testAllocation() {
        byte[] allocation1, allocation2, allocation3, allocation4;
        allocation1 = new byte[2*_1MB];
        allocation2 = new byte[2*_1MB];
        allocation3 = new byte[2*_1MB];
        allocation4 = new byte[4*_1MB]; //出现一次 Minor GC
    }

    public static void main(String[] args) {
        testAllocation();
    }
}

执行结果：

[GC (Allocation Failure) [PSYoungGen: 6146K->872K(9216K)] 6146K->4976K(19456K), 0.0138583 secs]
[Times: user=0.06 sys=0.00, real=0.01 secs]
Heap
PSYoungGen total 9216K, used 7339K [0x00000000ff600000, 0x0000000100000000,
0x0000000100000000)
eden space 8192K, 78% used [0x00000000ff600000,0x00000000ffc50e68,0x00000000ffe00000)
from space 1024K, 85% used [0x00000000ffe00000,0x00000000ffeda020,0x00000000fff00000)
to space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
ParOldGen total 10240K, used 4104K [0x00000000fec00000, 0x00000000ff600000,
0x00000000ff600000)
object space 10240K, 40% used [0x00000000fec00000,0x00000000ff002020,0x00000000ff600000)
Metaspace used 3420K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 371K, capacity 388K, committed 512K, reserved 1048576K

大对象回收分析

大对象直接进入老年代虚拟机提供一个参数 -XX:PretenureSizeThreshold 用来设置直接在老年代分配的对象的大小，如果对象大于这个值就会直接在老年代分配。这样做的目的是避免在 Eden 区及两个Survivor 区之间发生大量的内存复制。

设置参数：

-verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+UseParNewGC -XX:+PrintGCDetails -
XX:PretenureSizeThreshold=3145728

测试代码：

public class TestGCLog03 {
    private static final int _1MB = 1024 * 1024;

    /**
     * VM参数：（参数序号对应实验序号）
     *  -Xms20M -Xmx20M -Xmn10M -XX:+UseParNewGC -XX:+PrintGCDetails -XX:PretenureSizeThreshold=3145728
     */
    public static void testPreteureSizeThreshold() {
        byte[] allocation;
        allocation = new byte[4 * _1MB];
    }

    public static void main(String[] args) {
        testPreteureSizeThreshold();
    }
}

执行结果：

Heap
par new generation total 9216K, used 2214K [0x00000000fec00000, 0x00000000ff600000,
0x00000000ff600000)
eden space 8192K, 27% used [0x00000000fec00000, 0x00000000fee29be8, 0x00000000ff400000)
from space 1024K, 0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
to space 1024K, 0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
tenured generation total 10240K, used 4096K [0x00000000ff600000, 0x0000000100000000,
0x0000000100000000)
the space 10240K, 40% used [0x00000000ff600000, 0x00000000ffa00010, 0x00000000ffa00200,
0x0000000100000000)
Metaspace used 3430K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 373K, capacity 388K, committed 512K, reserved 1048576K

结果分析：

过上面的堆的内存占用情况很容易看出我们分配的4MB大小的对象直接被放到了老年代。

日志分析工具

日志工具简介

GC日志可视化分析工具GCeasy和GCviewer。通过GC日志可视化分析工具，我们可以很方便的看到JVM各个分代的内存使用情况、垃圾回收次数、垃圾回收的原因、垃圾回收占用的时间、吞吐量等，这些指标在我们进行JVM调优的时候是很有用的。

GCeasy是一款在线的GC日志分析器，可以通过GC日志分析进行内存泄露检测、GC暂停原因分析、JVM配置建议优化等功能，而且是可以免费使用（在线分析工具：https://gceasy.io/index.jsp）
GCViewer是一款实用的GC日志分析软件，免费开源使用，你需要安装jdk或者java环境才可以使用。软件为GC日志分析人员提供了强大的功能支持，有利于大大提高分析效率

测试准备

编写代码生成gc.log日志准备分析：

public class TestGCLog04 {
    private static final int _1MB = 1024 * 1024;

    /**
     * -XX:SurvivorRatio=8 -XX:+UseParallelGC -XX:+UseParallelOldGC  -XX:+PrintGCDetails -Xloggc:D://logs/gc.log
     */
    public static void main(String[] args) {
        ArrayList<byte[]> list = new ArrayList<byte[]>();
        for (int i = 0; i < 2000; i++) {
            byte[] arr = new byte[1024 * 1024];
            list.add(arr);
            try {
                Thread.sleep(20);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }
}

在d:/logs/gc.log 生成日志：

Java HotSpot(TM) 64-Bit Server VM (25.162-b12) for windows-amd64 JRE (1.8.0_162-b12), built on Dec
19 2017 20:00:03 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16454268k(6068260k free), swap 32906696k(20647740k free)
CommandLine flags: -XX:InitialHeapSize=104857600 -XX:MaxHeapSize=104857600 -XX:+PrintGC -
XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -
XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC
5.291: [GC (Allocation Failure) [PSYoungGen: 27642K->3064K(30720K)] 27642K->24839K(99328K),
0.2011370 secs] [Times: user=0.64 sys=0.01, real=0.20 secs]
Heap
PSYoungGen total 30720K, used 29578K [0x00000000fdf00000, 0x0000000100000000,
0x0000000100000000)
eden space 27648K, 95% used [0x00000000fdf00000,0x00000000ff8e4748,0x00000000ffa00000)
from space 3072K, 99% used [0x00000000ffa00000,0x00000000ffcfe1b0,0x00000000ffd00000)
to space 3072K, 0% used [0x00000000ffd00000,0x00000000ffd00000,0x0000000100000000)
ParOldGen total 68608K, used 21775K [0x00000000f9c00000, 0x00000000fdf00000,
0x00000000fdf00000)
object space 68608K, 31% used [0x00000000f9c00000,0x00000000fb143d50,0x00000000fdf00000)
Metaspace used 3947K, capacity 4568K, committed 4864K, reserved 1056768K
class space used 434K, capacity 460K, committed 512K, reserved 1048576K