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

2021-02-28 14:07:11   最后更新: 2021-02-28 14:07:11   访问数量:147




 

上一篇文章中,我们详细介绍了 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.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

 

 

对于线上持续运行的 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.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 -- 所有并行任务中,先执行完成的任务等待后执行完成的任务的耗时情况
  10. Termination Attempts -- 先执行完成的任务会尝试为未完成的任务分担工作,这一项显示了分担工作的耗时情况
  11. GC Worker Other -- 剩余其他工作的耗时情况
  12. GC Worker Total -- 每个并行任务工作的总耗时情况
  13. 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)

 

  1. 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. 线程在安全点之间运行的总耗时情况

 

 

如果你想了解到整个 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

 

 






java      gc      垃圾回收      g1      full_gc     


京ICP备2021035038号