G1垃圾收集器入门教程(7)——G1的垃圾收集日志

本教程涵盖的最后一个主题会介绍如何使用日志信息来分析 G1 收集器的性能。本节会提供一些选项和开关的快速概述,你可以用来收集输出至日志中的数据和信息。

设置日志详情

你可以将日志设置为三个不同的细节级别。

(1)-verbosegc

等同于-XX:+PrintGC开关,可以将日志的详细级别设置为 fine。示例输出:

[GC pause (G1 Humongous Allocation) (young) (initial-mark) 24M- >21M(64M), 0.2349730 secs]
[GC pause (G1 Evacuation Pause) (mixed) 66M->21M(236M), 0.1625268 secs]

(2)-XX:+PrintGCDetails

可以将日志的详细级别设置为 finer。这个选项能够显示以下信息:

  • 显示每个阶段耗费的平均时间、最小时间和最大时间。
  • 根节点扫描、更新 RSet(带有经过处理的缓冲信息)、RSet 扫描、对象复制、终止(带有尝试次数)等时间。
  • 还可以显示“其他”时间,诸如选择 CSet、处理引用、引用入队和释放 CSet等操作耗费的时间。
  • 显示 Eden 区、Survivor 区和整个堆内存的占用情况。

示例输出:

[Ext Root Scanning (ms): Avg: 1.7 Min: 0.0 Max: 3.7 Diff: 3.7]
[Eden: 818M(818M)->0B(714M) Survivors: 0B->104M Heap: 836M(4096M)->409M(4096M)]

(3)-XX:+UnlockExperimentalVMOptions 和 -XX:G1LogLevel=finest

可以将日志的详细级别设置为 finest。这个级别类似于 finer,但是还包含各个工作线程的信息。示例输出:

[Ext Root Scanning (ms): 2.1 2.4 2.0 0.0
           Avg: 1.6 Min: 0.0 Max: 2.4 Diff: 2.3]
       [Update RS (ms):  0.4  0.2  0.4  0.0
           Avg: 0.2 Min: 0.0 Max: 0.4 Diff: 0.4]
           [Processed Buffers : 5 1 10 0
           Sum: 16, Avg: 4, Min: 0, Max: 10, Diff: 10]

确定时间

有两个开关可以确定如何在 GC 日志中显示时间。

(1)-XX:+PrintGCTimeStamps

显示自 JVM 启动以来已经流逝的时间。输出示例:

1.729: [GC pause (young) 46M->35M(1332M), 0.0310029 secs]

(2)-XX:+PrintGCDateStamps

为每个日志条目添加日期和时间的前缀。输出示例:

2012-05-02T11:16:32.057+0200: [GC pause (young) 46M->35M(1332M), 0.0317225 secs]

理解 G1 日志

为了理解 G1 日志,本节将演示真实的 GC 日志输出,然后给出一些专业术语的定义。以下示例将演示 G1 日志输出,并且会解释你将在日志中找到的术语和取值。

注意:如果想要了解更多信息,那么可以参考Poonam Bajaj博客的G1垃圾收集日志的相关文章

G1 日志的术语索引

并行时间
外部根节点扫描
更新记忆集合
扫描记忆集合
对象复制
终止时间
垃圾收集工作线程的结束时间
垃圾收集工作线程的其他时间
清空卡表
其他时间
收集集合
引用处理
引用入队
释放收集集合

并行时间

414.557: [GC pause (young), 0.03039600 secs] [Parallel Time: 22.9 ms]
[GC Worker Start (ms): 7096.0 7096.0 7096.1 7096.1 706.1 7096.1 7096.1 7096.1 7096.2 7096.2 7096.2 7096.2
       Avg: 7096.1, Min: 7096.0, Max: 7096.2, Diff: 0.2]
  • Parallel Time:造成停顿的主要并行部分的总运行时间。
  • Worker Start:各个工作线程启动的时间戳。

注意:日志是按照线程 ID 排序的,每个日志条目都是一致的。

外部根节点扫描

[Ext Root Scanning (ms): 3.1 3.4 3.4 3.0 4.2 2.0 3.6 3.2 3.4 7.7 3.7 4.4
     Avg: 3.8, Min: 2.0, Max: 7.7, Diff: 5.7]
  • Ext Root Scanning:扫描外部根节点(诸如指向堆内存的系统字典之类的东西)耗费的时间。

更新记忆集合

[Update RS (ms): 0.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Avg: 0.0, Min: 0.0, Max: 0.1, Diff: 0.1]
   [Processed Buffers : 26 0 0 0 0 0 0 0 0 0 0 0
    Sum: 26, Avg: 2, Min: 0, Max: 26, Diff: 26]
  • Update RS:在停顿开始之前,如果缓冲区已经填满,但是并发细化线程尚未处理这些缓冲区,那么就必须先更新这些缓冲区。耗费时间取决于卡片的密度。卡片越多,耗费时间就越长。

扫描记忆集合

[Scan RS (ms): 0.4 0.2 0.1 0.3 0.0 0.0 0.1 0.2 0.0 0.1 0.0 0.0 Avg: 0.1, Min: 0.0, Max: 0.4, Diff: 0.3]F
  • Scan RS:查找指向收集集合(CSet)的指针。

对象复制

[Object Copy (ms): 16.7 16.7 16.7 16.9 16.0 18.1 16.5 16.8 16.7 12.3 16.4 15.7 Avg: 16.3, Min: 12.3, Max:  18.1, Diff: 5.8]
  • Object Copy:每个线程用于复制和排空对象各自耗费的时间。

终止时间

[Termination (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
0.0 Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0] [Termination Attempts : 1 1 1 1 1 1 1 1 1 1 1 1 Sum: 12, Avg: 1, Min: 1, Max: 1, Diff: 0]
  • Termination:当某个工作线程完成其特定对象集合的复制和扫描时,它就会进入终止协议。它会查找能够侵占的工作,一旦完成了该项工作,它会再次进入终止协议。线程终止会试图统计侵占工作的全部尝试次数。

垃圾收集工作线程的结束时间

[GC Worker End (ms): 7116.4 7116.3 7116.4 7116.3 7116.4 7116.3 7116.4 7116.4 7116.4 7116.4 7116.3 7116.3
    Avg: 7116.4, Min: 7116.3, Max: 7116.4, Diff:   0.1]
[GC Worker (ms): 20.4 20.3 20.3 20.2 20.3 20.2 20.2 20.2 20.3 20.2 20.1 20.1
     Avg: 20.2, Min: 20.1, Max: 20.4, Diff: 0.3]
  • GC Worker End:GC 的各个工作线程停止时的时间戳。
  • GC Worker:GC 的各个工作线程耗费的时间。

垃圾收集工作线程的其他时间

[GC Worker Other (ms): 2.6 2.6 2.7 2.7 2.7 2.7 2.7 2.8 2.8 2.8 2.8 2.8
    Avg: 2.7, Min: 2.6, Max: 2.8, Diff: 0.2]
  • GC Worker Other:对于每个 GC 线程来说,这段时间不是工作线程在先前列出的任何阶段中所耗费的。这段时间非常短。在过去,我们看到过极高的耗时,它们可以归因为 JVM 的其他部分的性能瓶颈(例如,分层增加代码缓存(Code Cache)的占用率)。

清空卡表

[Clear CT: 0.6 ms]
  • Clear CT:清空扫描元数据的RSet的卡表(Card Table)所耗费的时间。

其他时间

[Other: 6.8 ms]
  • Other:GC 停顿的各种其他的连续阶段所耗费的时间。

收集集合

[Choose CSet: 0.1 ms]
  • Choose CSet:最终确定待收集的区域集合所耗费的时间。这段时间通常很短,当必须选择老的CSet时,耗费的时间会稍长。

引用处理

[Ref Proc: 4.4 ms]
  • Ref Proc:处理稍早的 GC 阶段遗漏的软引用、弱引用等等所耗费的时间。

引用入队

[Ref Enq: 0.1 ms]
  • Ref Enq:将软引用、弱引用等等放入待处理列表所耗费的时间。

释放收集集合

[Free CSet: 2.0 ms]
  • Free CSet:释放刚刚收集的区域集合的内存空间所耗费的时间,包括每个区域的记忆集合(RSet)。