通过 G1 GC Log 重新认识 G1 垃圾回收器

1. 引言

上一篇文章中，我们详细介绍了 CMS 的配置参数以及 gc log 的解读：

JAVA 性能调优 -- 带你解读 CMS GC 日志

但事实上，g1 由于他的诸多优势已经越来越多的受到 java 程序员的青睐，尤其在机器内存日益增大的今天，巨大的内存分区无疑会让 CMS 回收时间过长，而这已经成为程序员们无法忍受 CMS 最重要的一个原因。

此前，我们已经深入介绍了 g1 垃圾回收的机制以及相应的配置：

驾驭一切的垃圾收集器 -- G1

本文，我们就来详细介绍一下 g1 的 gc log，让你能够通过 g1 的 gc log 分析出性能问题出在哪里。

当然，上文介绍的两个实用的 gc log 分析工具：GCeasy 与 GC Viewer，都可以直接用于分析 g1 的 gc log，本文就不再赘述了。

2. GC log 相关的参数配置

2.1 日志打印的相关参数

上一篇文章中介绍的 gc 日志打印的相关参数在 g1 垃圾回收器中仍然是可用的：

-Xloggc:<path> # gc log 的输出路径 -XX:+PrintGC # 输出 gc log -XX:+PrintGCDetails # 输出 gc 详细信息 -XX:+PrintGCDateStamps # 在 gc log 中记录 gc 启动时的系统时间 -XX:+PrintGCTimeStamps # 在 gc log 中记录 gc 启动时相对于 jvm 启动的相对时间

2.2 G1 垃圾收集器诊断参数

-XX:+UnlockDiagnosticVMOptions # 解锁诊断参数 -XX:+G1SummarizeConcMark # jvm 退出时汇总并发标记 -XX:+G1PrintHeapRegions # 打印垃圾收集的 region 信息 -XX:G1PrintRegionLivenessInfo # 打印在并发标记周期的清理阶段每个区的活跃数据信息 -XX:+G1SummarizeRSetStats # 打印 RSet 回收情况 -XX:G1SummarizeRSetStatsPeriod=period # 打印 RSet 回收报告周期（每 period 次 GC 打印一次报告）

2.3 G1 垃圾收集器实验参数

-XX:+UnlockExperimentalVMOptions # 解锁实验参数 -XX:G1LogLevel=fine, finer, finest # GC 日志级别 -XX:+G1TraceEagerReclaimHumongousObjects # 跟踪并输出超大对象回收相关信息 -XX:+G1ConcRegionFreeingVerbose # Debug JVM

3. gc 日志的自动分割

对于线上持续运行的 java 程序来说，gc 日志不断地输出，会导致单个 GC 日志文件过大，这十分不利于我们去获取和分析，以一定的规则自动切割 gc 日志文件无疑对我们来说更为方便。

下面我们就来介绍两种常见的日志自动分割方式的配置。

3.1 循环分割与覆盖

-Xloggc:/data/var/gclog/gc.log -XX:+UseGCLogFileRotation # 开启循环分割 -XX:NumberOfGCLogFiles=5 # gc log 文件数 -XX:GCLogFileSize=20M # 单个 gc log 文件最大容量

通过这个配置，JVM的一个日志文件达到了20M以后，就会写入另一个新的文件，最多会有5个日志文件，他们的名字分别是：gc.log.0、gc.log.1、gc.log.2、gc.log.3、gc.log.4。

当 gc.log.4 文件达到 20M 以后，JVM 就会删除并重新创建 gc.log.0，并向其中写入新的 gc log。

3.1.1 循环分割覆盖日志的问题

这个方式是非常不推荐使用的。因为他存在以下问题：

• 旧日志丢失

显而易见，当 gc.log.4 日志达到配置中的 20M 大小，我们就会丢失 gc.log.0 中的内容，这可能造成一些问题我们无法定位和排查。

• 日志会变混乱

尽管日志是循环覆盖的，但每当重启 jvm，gc 日志都会从 gc.log.0 开始写起，这就会造成你无法知道到底哪个 gc 日志是新的，哪个是旧的，他们掺杂在一起。

• 日志难以分析

如果你想要使用日志分析工具，那么你就需要提前合并上传多个文件。

3.2 按重启时间自动分割

-Xloggc:/data/var/gclog/gc-%t.log

这种方式是更为推荐的，%t 会给文件名添加时间戳后缀，格式是YYYY-MM-DD_HH-MM-SS。

这样，每次 JVM 重启以后，会生成新的日志文件，新的日志也不会覆盖老的日志。

4. G1 的 gc log

4.1 young gc

如图所示，相较于 CMS 的 GC 日志，G1 的 GC 日志信息更为详细。

主要包含了以下六部分内容：

1. 基本信息
2. 并行任务信息（STW）
3. 串行任务信息
4. 其他串行操作信息
5. 各代空间变化统计
6. 回收花费时间统计

4.1.1 基础信息

1. 2016-12-12T10:40:18.811-0500 -- 通过设置 ‘-XX:+PrintGCDateStamps’ 得到GC发生的准备日期时间
2. 29.959 -- JVM 启动到当前时间的间隔时间
3. G1 Evacuation Pause (young) -- 收集类型
4. 0.0305171 sec -- 整个回收过程花费的时间

4.1.2 并行任务信息（这一过程会 stop the world）

1. Parallel Time -- 并行收集任务执行总时长
2. GC Workers -- 并行收集线程数（可以通过 -XX:ParallelGCThreads 设置）
3. GC Worker Start -- 各个并行线程启动时间信息（相对于 JVM 启动到到当前时间的时间间隔）
4. Ext Root Scanning -- 外部根区(堆外区，线程栈根，JNI，全局变量，系统目录，classloader等)扫描消耗时间
5. Update RS -- 在每次开始收集之前都要进行Rset更新，保证RSet是最新的。-XX:MaxGCPauseMillis 参数是限制G1的暂停时间，一般 RSet 更新的时间小于 10% 的目标暂停时间是比较可取的。如果花费在 RSetUpdate 的时间过长，可以修改其占用总暂停时间的百分比 -XX:G1RSetUpdatingPauseTimePercent。这个参数的默认值是10
6. Scan RS -- 扫描每个 Region 的 RSet 的耗时情况
7. Code Root Scanning -- 扫描被待收集集合引用的编译源码根节点的耗时情况
8. Object Copy -- 将待收集集合中所有存活的对象拷贝到新的区域的耗时情况
9. Termination -- 所有并行任务中，先执行完成的任务等待后执行完成的任务的耗时情况
   1. Termination Attempts -- 先执行完成的任务会尝试为未完成的任务分担工作，这一项显示了分担工作的耗时情况
10. GC Worker Other -- 剩余其他工作的耗时情况
11. GC Worker Total -- 每个并行任务工作的总耗时情况
12. GC Workder End -- 每个并行任务完成时，自 jvm 启动以来的时间情况

4.1.3 串行任务信息

1. Code Root Fixup -- 遍历指向 CSet 的方法，修正指针的耗时
2. Code Root Purge -- 清理 code root table 的耗时
3. Clear CT -- 清除卡表中的脏 cards 的耗时

4.1.4 其他串行操作信息

1. Choose CSet -- 选取 CSet
2. Ref Proc -- 处理 STW 引用处理器发现的 soft/weak/final/phantom/JNI 引用
3. Ref Enq -- 将引用排列到相应的 reference 队列中
4. Redirty Cards -- 在回收过程中被修改的 cards 标记为脏卡
5. Humongous Register -- 巨型对象区域收集评估
6. Humongous Reclaim -- 巨型对象区域收集
7. Free CSet -- 释放 CSet

4.1.5 各个代的空间变化统计

1. Eden: 1097.0M(1097.0M)->0.0B(967.0M) -- 收集后 eden 区占用空间及总容量变化
2. Survivors: 13.0M->139.0M -- survivor 区空间变化情况
3. Heap: 1694.4M(2048.0M)->736.3M(2048.0M) -- 堆内存占用空间及总容量变化

4.1.6 垃圾回收花费的时间

1. user=0.08 -- 用户态处理总耗时
2. sys=0.00 -- 内核态处理总耗时
3. real=0.03 -- 总花费时间

4.2 并发标记阶段

如图所示，并发标记主要分为六个步骤：

1. 初始标记（STW）
2. 初次并发标记
3. 并发标记
4. 最终标记
5. 清除（STW）
6. 并发清除

4.2.1 初始标记

GC pause (G1 Evacuation Pause) (young) (initial-mark)

初始标记是 Young GC 的一部分，他的主要工作是寻找所有可达的存活对象。

初始标记阶段会设置两种 TAMS 变量来区分现存的对象和并行标记时才分配的对象。

4.2.2 初次并发标记

GC concurrent-root-region-scan-start / GC concurrent-root-region-scan-end

与上一阶段不同，这个阶段 GC 的线程可以和应用线程并发运行，他的主要工作是进行根分区扫描，扫描初始标记的对象和 survivor 分区中引用的对象。

4.2.3 并发标记

GC concurrent-mark-start / GC concurrent-mark-end

这一阶段就是 -XX:ConcGCThreads 参数指定并发线程数的并发标记阶段。

这一阶段会并发标记所有非完全空闲的分区的存活对象，使用 SATB 算法标记各个分区。

4.2.4 最终标记

GC remark [ Finalize Marking / GC ref-proc / Unloading]

这一阶段的主要工作是处理 SATB 缓冲，标记上一阶段没有标记的新生存活对象。

4.2.5 清除阶段

GC cleanup

1. 每个区域分别统计存活对象。在card bitmap标记初始标记之后分配的对象，在Region bitmap标记有存货对象的区域
2. 交换bitmaps，为下一次标记做准备
3. 释放和清理死去的老年区域和没有存货数据的巨型数据区域
4. 清除没有存活对象的区域的RSet
5. 将老年区域根据存活率进行排序
6. 并发的将无效的类从metaspace卸载

4.2.6 并发清除

GC concurrent-cleanup-start / GC concurrent-cleanup-end

1. 清理RSet，包括card cache和code root table
2. 当区域完全清除后，添加到临时队列，清除结束后，将临时队列合并到第二空闲区域队列，等待被添加到主空闲队列

4.3 Mixed GC

一旦并发标记完成，紧接着就会进行一次 mixed gc。

如上图所示，mixed gc 与 young gc 在日志中表现基本上是相同的，这里就不再赘述了。

mixed gc 的日志与 young gc 的日志仅存在两点区别：

1. 有 mixed 标记 GC pause (G1 Evacuation Pause) (mixed)
2. CSet 会包含通过并发标记确定的老年区域

4.4 FULL GC

在 G1 中，full gc 是我们要极力避免的，他是整个堆内存的完整收集，因此，G1 中的 full gc 通常意味着一个漫长的 stw 暂停。

full gc 的日志中包含有三部分信息：

1. 触发原因
2. 发生频率
3. full gc 的耗时

4.5 汇总信息

通过 -XX:+PrintGCApplicationStoppedTime 参数和 -XX:+PrintGCApplicationConcurrentTime 参数可以产生汇总信息日志：

他包含三部分信息：

1. 线程被暂停的总时间
2. 从线程准备暂停到他运行到安全点开始暂停这一过程花费的总时间
3. 线程在安全点之间运行的总耗时情况

5. GC 日志的高级参数

如果你想了解到整个 GC 过程中更加详细的内容，你可以设置下面三个参数：

-XX:+PrintAdaptiveSizePolicy # 每次 GC 后根据本次 GC 的时间、吞吐量、内存占用量重新计算 Eden、From 和 To 区的大小并打印 -XX:+PrintTenuringDistribution # 打印 Survivor 对象年龄分布 -XX:+PrintReferenceGC # 打印各种引用的处理时间

附录 -- 参考资料

• 本文翻译整理自：https://www.redhat.com/en/blog/collecting-and-reading-g1-garbage-collector-logs-part-2