[解密JVM-17] 垃圾回收：日志分析

1、常见参数列表

-XX:+PrintGC

  输出 GC 日志，类似-verbose:gc。
  测试代码：

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

    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[] agrs) {
        testAllocation();
    }
}

  对测试代码使用参数-Xms10m -Xmn10m -XX:+PrintGC，可以看到输出如下：

  可以看到是一个比较简陋的 GC 日志信息。

-XX:+PrintGCDetails

  输出详细的 GC 日志信息，对上面的测试代码使用参数-Xms10m -Xmn10m -XX:+PrintGCDetails，可以看到输出如下：

  可以看出，在上面参数的基础上有更详细的信息。

-XX:+PrintGCTimeStamps

  输出 GC 的时间戳，以 JVM 启动时间为基准。上面代码参数为-Xms10m -Xmn10m -XX:+PrintGCDetails -XX:+PrintGCTimeStamps，输出结果如下：

  可以看出多了时间戳。

-XX:+PrintGCDateStamps

  输出 GC 的时间戳，以日期的形式。上面代码参数为-Xms10m -Xmn10m -XX:+PrintGCDetails -XX:+PrintGCDateStamps，输出结果如下：

  可见，时间戳的表示形式变为日期的形式。

-XX:+PrintHeapAtGC

  在 GC 的前后打印出堆的信息，上面代码运行参数为-Xms10m -Xmn10m -XX:+PrintHeapAtGC，输出结果如下：

2、日志信息解析

  上面的参数会打印出各种形式的日志信息，那么如何解读这些信息呢？

  日志信息包括以下几个部分：
  1、GC 的类型：有 GC 和 Full GC 两种，前者只在新生代进行，后者包括新生代、老年代、永久代；
  2、GC 的触发原因，如：Allocation Failure；
  3、堆在 GC 前后的大小；
  4、GC 持续的时间；

  比如，Minor GC 日志为：

[GC (Allocation Failure) [PSYoungGen: 5996K->840K(8704K)] 5996K->4944K(14336K), 0.0030231 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

  分析结果为：

  Full GC 日志为：

[Full GC (Ergonomics) [PSYoungGen: 840K->0K(8704K)] [ParOldGen: 4104K->4692K(10240K)] 4944K->4692K(18944K), [Metaspace: 3174K->3174K(1056768K)], 0.0075421 secs] [Times: user=0.09 sys=0.00, real=0.01 secs] 

  分析结果为：

3、日志分析案例

  测试代码为：

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

    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[] agrs) {
        testAllocation();
    }
}

  JDK8 环境下，启动参数为：-Xms10m -Xmn10m -XX:+PrintGCDetails

  运行结果为：

  可以看出，Eden 占用是 7680KB 的 83%，大约 6MB 多。老年代占用了 10240KB 的 45%，大约 4MB 多。也就是说，前面分配的三个对象在 Eden 区，当分配第四个 4MB 的对象时，Eden 放不下，于是触发了 GC，通过 GC 后的年轻代和老年代的占用情况可知：最后放的 4MB 对象是直接放到老年代的。

4、GC 日志分析工具

  前面的代码量很少，可以肉眼分析，但是当一个大型工程启动后，GC 的日志可就特别多了，考肉眼去看是不现实的，于是出现一些日志分析工具。

  我们使用参数-Xloggc:./logs/gc.log把 GC 日志写入到一个文件中，然后使用日志分析工具来解析这个日志。

  测试代码和上面的一样，我们使用参数-Xms10m -Xmn10m -Xloggc:./logs/gc.log，就可以在工程路径的 logs 目录下看到 gc.log。

  日志的内容为：

Java HotSpot(TM) 64-Bit Server VM (25.231-b11) for windows-amd64 JRE (1.8.0_231-b11), built on Oct  5 2019 03:11:30 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16629224k(6865060k free), swap 27639272k(10100816k free)
CommandLine flags: -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=4257081344 -XX:MaxNewSize=10485760 -XX:NewSize=10485760 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
0.138: [GC (Allocation Failure)  5996K->4912K(14336K), 0.0031180 secs]
0.141: [Full GC (Ergonomics)  4912K->4692K(18944K), 0.0074975 secs]

  当工程很大的时候，这个日志内容是很多的，这里推荐一个 GC 日志分析工具：GCViewer。

  还有网页在线版的GCeasy。