看懂 ParallelGC 的日志

发表于 更新于 分类于 Waline： 阅读次数：

在排查垃圾回收相关的问题时，一个必不可少的技能就是要能看懂 Java 的垃圾回收日志。本文将介绍打印 GC 日志相关的 JVM 参数，以及使用不同参数时 JVM 将会打印出的日志内容。

JDK 版本

1
2
3
openjdk version "1.8.0_232"
OpenJDK Runtime Environment (AdoptOpenJDK)(build 1.8.0_232-b09)
OpenJDK 64-Bit Server VM (AdoptOpenJDK)(build 25.232-b09, mixed mode)

示例代码

在演示过程中，我们将通过在死循环中构造大对象的方式来触发垃圾回收

1
2
3
4
5
6
7
8
public class GCExample {
    public static void main(String[] args) {
        String[] strings;
        while (true) {
            strings = new String[1024];
        }
    }
}

同时，为了让垃圾回收更早的开始，我们还需要指定一个较小的堆内存，比如我选择只分配 10MB 的空间。

1
2
-Xmx10m
-Xms10m

GC 日志相关的 JVM 参数

与 GC 日志相关的 JVM 参数有如下 8 个：

参数名 参数含义
-XX:+PrintGC 输出简要 GC 日志
-verbose:gc 等同于 -XX:+PrintGC
-XX:+PrintGCDetails 输出详细 GC 日志
-Xloggc:gc.log 输出 GC 日志到文件 gc.log
-XX:+PrintGCTimeStamps 输出 GC 的时间戳（以 JVM 启动到当期的总时长的时间戳形式）
-XX:+PrintGCDateStamps 输出 GC 的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC 在进行 GC 的前后打印出堆的信息
-XX:+PrintReferenceGC 打印年轻代各个引用的数量以及时长

-XX:+PrintGC 与 -verbose:gc

虽然上面说这两个参数是等价的，但是，-verbose:gc 是一个标准的参数，而 -XX:+PrintGC 则在 JDK 9 之后被标为废弃的 (deprecated)，所以建议使用 -verbose:gc 代替 -XX:+PrintGC。

打开 -verbose:gc

使用这个参数将会打开简略的 GC 日志。打开这个参数并运行程序，很快就可以看到这样的 GC 日志：

1
[GC (Allocation Failure)  2520K->472K(9728K), 0.0005722 secs]

我们将上面的日志拆分开来：

  • GC 代表这次垃圾回收的类型。GC 代表发生了 Minor GC，Full GC 代表发生了 Full GC
  • Allocation Failure 简述了发生 GC 的原因。在这个例子中，是因为在年轻代中没有合适的空间导致新的对象分配失败，从而发生 GC
  • 2520K->472K 说明了年轻代的占用量变化。在这个例子中，年轻代的使用量从 2520KB 减少到了 472KB
  • 9728K 表示整个堆的大小
  • 0.0005722 secs 表示了本次 GC 消耗的时间

打开 -XX:+PrintGCDetails

使用这个参数后，将会打印详细的 GC 日志，它打印的内容包含了 -verbose:gc 参数打印的内容。

1
[GC (Allocation Failure) [PSYoungGen: 2048K->0K(2560K)] 2500K->452K(9728K), 0.0003785 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

这个参数打印的日志与上一个参数打印的日志有一部分重合，这里我们关注新增的内容：

  • [PSYoungGen: 2048K->0K(2560K)] 表明了使用的垃圾回收器、年轻代的占用量变化，和年轻代的大小
  • 2500K->452K(9728K) 表明了整个堆的占用量变化，和整个堆的大小
  • [Times: user=0.00 sys=0.00, real=0.00 secs] 表示本次 GC 消耗的时间
    • user 代表垃圾回收器消耗的 CPU 时间
    • sys 代表系统调用或等待系统事件消耗的时间
    • real 代表应用实际停止的时间，近似于 (user + sys) / 垃圾回收器使用的线程数

打开 -XX:+PrintGCTimeStamps

这个参数不影响日志的详细程度，在打开之后，日志中会出现从 JVM 启动到出现日志时的毫秒数，比如下面例子的 1.523。

1
1.523: [GC (Allocation Failure) [PSYoungGen: 2141K->96K(2560K)] 4805K->2776K(9728K), 0.0004359 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

打开 -XX:+PrintGCDateStamps

这个参数也不影响日志的详细程度，在打开之后，日志头部会加上打印日志的时间和时区，比如下面例子的 2020-02-06T10:13:08.634-0800。

1
2020-02-06T10:13:08.634-0800: 1.122: [GC (Allocation Failure) [PSYoungGen: 2048K->0K(2560K)] 3328K->1280K(9728K), 0.0004243 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

打开 -XX:+PrintHeapAtGC

使用这个参数后，在打印 GC 日志时，会同时打印出堆在 GC 前后的信息，即根据不同的内存区域，分别显示在垃圾回收前后的空间使用情况。同时，日志中还以 [bottom,top,end) 的格式展现出了各个内存区域的地址，其中 bottom 为这个区域的起始位置，top 为这个区域当前的顶部位置，end 为这个区域可使用的地址上限 [^1]。

此外，日志中关于 Metaspace 相关的信息可以参考注脚 4 [^4] 指向的那篇回答。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
{Heap before GC invocations=1 (full 0):
 PSYoungGen      total 2560K, used 2047K [0x00000007bfd00000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 2048K, 99% used [0x00000007bfd00000,0x00000007bfeffe78,0x00000007bff00000)
  from space 512K, 0% used [0x00000007bff80000,0x00000007bff80000,0x00000007c0000000)
  to   space 512K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007bff80000)
 ParOldGen       total 7168K, used 0K [0x00000007bf600000, 0x00000007bfd00000, 0x00000007bfd00000)
  object space 7168K, 0% used [0x00000007bf600000,0x00000007bf600000,0x00000007bfd00000)
 Metaspace       used 3045K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 320K, capacity 388K, committed 512K, reserved 1048576K
2020-02-06T10:21:05.317-0800: 0.219: [GC (Allocation Failure) [PSYoungGen: 2047K->496K(2560K)] 2047K->512K(9728K), 0.0019061 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
Heap after GC invocations=1 (full 0):
 PSYoungGen      total 2560K, used 496K [0x00000007bfd00000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 2048K, 0% used [0x00000007bfd00000,0x00000007bfd00000,0x00000007bff00000)
  from space 512K, 96% used [0x00000007bff00000,0x00000007bff7c010,0x00000007bff80000)
  to   space 512K, 0% used [0x00000007bff80000,0x00000007bff80000,0x00000007c0000000)
 ParOldGen       total 7168K, used 16K [0x00000007bf600000, 0x00000007bfd00000, 0x00000007bfd00000)
  object space 7168K, 0% used [0x00000007bf600000,0x00000007bf604000,0x00000007bfd00000)
 Metaspace       used 3045K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 320K, capacity 388K, committed 512K, reserved 1048576K
}

打开 -XX:+PrintReferenceGC

打开这个参数后，就可以看到各种引用的数量，以及对其垃圾回收所消耗的时长。

1
[GC (Allocation Failure) [SoftReference, 0 refs, 0.0000125 secs][WeakReference, 0 refs, 0.0000054 secs][FinalReference, 0 refs, 0.0000045 secs][PhantomReference, 0 refs, 0 refs, 0.0000222 secs][JNI Weak Reference, 0.0000037 secs][PSYoungGen: 2112K->64K(2560K)] 3488K->1456K(9728K), 0.0005389 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

[^1]: Meaning of heap memory addresses in GC logs using -XX:+PrintHeapAtGC?
[^2]: Parallel GC - Plumber
[^3]: Parallel Full GC - Plumber
[^4]: Understanding metaspace line in JVM heap printout