如何理解GC日志？

写在前面

本文隶属于专栏《100个问题搞定Java虚拟机》，该专栏为笔者原创，引用请注明来源，不足和错误之处请在评论区帮忙指出，谢谢！

本专栏目录结构和文献引用请见100个问题搞定Java虚拟机

解答

如何设置 GC 日志？

-XX:+PrintGC 输出GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）
-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2021-05-16T21:53:59.234+0800）
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的输出路径

理解GC日志

为了输出 GC 日志，我们需要做些准备

Java代码

public class GCDemo {
    public static void main(String[] args) {
        int[] a;
        while(true){
            a = new int[100 * 1024 * 1024];
            a[0] = 1;
        }
    }
}

JVM配置

-XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:./gclogs

软硬件配置参考

JDK版本号：1.8.0_192-b12

上面的代码运行之后 GC 日志打印如下所示：

日志分析

我们只看上图中蓝线圈中的部分：

2021-05-16T23:28:29.072-0800: 1.123: [GC (Allocation Failure) [PSYoungGen: 560K->544K(141824K)] 2458168K->2458152K(2938368K), 0.0266116 secs] [Times: user=0.24 sys=0.00, real=0.02 secs] 
2021-05-16T23:28:29.098-0800: 1.150: [Full GC (Allocation Failure) [PSYoungGen: 544K->0K(141824K)] [ParOldGen: 2457608K->432K(121344K)] 2458152K->432K(263168K), [Metaspace: 3044K->3044K(1056768K)], 0.1779021 secs] [Times: user=0.04 sys=0.16, real=0.18 secs] 

最前面的数字2021-05-16T23:28:29.072-0800:代表日志打印的时间。

“1.123:”和“1.150:”代表了GC发生的时间，这个数字的含义是从Java虚拟机启动以来经过的秒数。

GC日志开头的“[GC”和“[Full GC”说明了这次垃圾收集的停顿类型。

如果有“Full”，说明这次GC是发生了Stop-The-World的。如果是调用 System.gc()方法所触发的收集，那么在这里将显示“[Full GC(System)”。

Allocation Failure – 引起垃圾回收的原因. 本次GC是因为年轻代中没有任何合适的区域能够存放需要分配的数据结构而触发的.

接下来的“[PSYoungGen:”表示GC发生的区域，这里显示的区域名称与使用的GC收集器是密切相关的，

例如上面样例所使用的Parallel Scavenge收集器， 那它配套的新生代称为“PSYoungGen”，

Serial 收集器中的新生代名为“Default New Generation"”，所以显示的是“[Defnew”。

如果是ParNew收集器，新生代名称就会变为“[ParNew”，意为“Parallel New Generation”。老年代和永久代同理，名称也是由收集器决定的。

后面方括号内部的"560K->544K(141824K)"含义是“GC前该内存区域已使用容量一>GC后该内存区域已使用容量(该内存区域总容量)”。

而在方括号之外的"2458168K->2458152K(2938368K)"表示“GC前Java堆已使用容量->GC后Java雄已使用容量(Java 堆总容量)”。

再往后，“0.0266116 secs”表示该内存区域GC所占用的时间，单位是秒。

最后的“[Times: user=0.24 sys=0.00, real=0.02 secs] ”，这里面的user、sys和real与Linux的time命令所输出的时间含义一致，分别代表用户态消耗的CPU 时间、内核态消耗的CPU事件和操作从开始到结東所经过的墙钟时间(Wall Clock Time)。

CPU时间与墙钟时间的区别

墙钟时间包括各种非运算的等待耗时，例如等待磁盘IO、等待线程阻塞，而CPU时间不包括这些耗时，但当系统有多CPU或者多核的话，多线程操作会叠加这些CPU时间，所以读者看到user或sys时间超过real时间是完全正常的。

GCeasy

上图是运行很短时间的 GC 日志，如果是长时间的 GC 日志，我们很难通过文本形式去查看整体的 GC 性能。
推荐一个比较好用的 GC 日志分析工具——GCeasy.

官网地址：https://gceasy.io/

GCeasy是一款在线的GC日志分析器，可以通过GC日志分析进行内存泄露检测、GC暂停原因分析、JVM配置建议优化等功能，而且是可以免费使用的（有一些服务是收费的）。

以我上面的GC日志为例，进行在线分析以后结果如下：

1. JVM的各个分代区域分配的内存及使用峰值的内存

2. 关键性能指标：吞吐量及GC暂停平均时间、最大时间、各个时间段的比例。

3. GC数据统计

4. 其他的数据统计