乐趣区

译深入理解G1的GC日志一

jiezi

本文翻译自：https://www.redhat.com/en/blog/collecting-and-reading-g1-garbage-collector-logs-part-2?source=author&term=22991

这篇文章将深入研究 G1 的日志和调优参数。为了在实际工作中对 G1 进行调优，作为开发者的你需要理解 G1 垃圾收集器的每个步骤，以及每个步骤在整个垃圾收集周期中的作用。为了方便读者学习，这篇文章将 G1 的日志参数分为等级递增的三块，这篇文章将会分别介绍每一部分参数的作用和调优时候使用的场景。

  1. 基础参数 – 在生产中使用 G1 收集器，必须使用这些参数
  2. 高级参数 – 随着应用的成熟或业务负载的增加，需要使用这些参数针对某些问题进行调优。
  3. Debug 参数 – 这些参数是用来解决特定的性能问题，如果某个问题在非生产环境中无法复现，才会在生产环境中使用这些参数排查问题。

基础参数

如果你要在生产环境中使用 G1 GC，下面这些跟日志相关的参数是必备的，有了这些参数，你才能排查基本的垃圾回收问题。

使用 -XX:GCLogFileSize 设置合适的 GC 日志文件大小，使用 -XX:NumberOfGCLogFiles 设置要保留的 GC 日志文件个数，使用 -Xloggc:/path/to/gc.log 设置 GC 日志文件的位置，通过上面三个参数保留应用在运行过程中的 GC 日志信息，我建议最少保留一个星期的 GC 日志，这样应用的运行时信息足够多的，方便排查问题。

新生代收集

和其他垃圾收集器一样，G1 也使用 -XX:PrintGCDetails 打印出详细的垃圾收集日志，下面这张图是新生代收集的标准流程，我在这里将它分成了 6 个步骤：

  1. 四个关键信息

    • 新生代垃圾收集发生的时间——2016-12-12T10:40:18.811-0500，通过设置 -XX:+PrintGCDateStamps 参数可以打印出这个时间；
    • JVM 启动后的相对时间——25.959
    • 这次收集的类型——新生代收集，只回收 Eden 分区
    • 这次收集花费的时间——0.0305171s，即 30ms

  2. 列出了新生代收集中并行收集的详细过程

    • Parallel Time：并行收集任务在运行过程中引发的 STW（Stop The World）时间，从新生代垃圾收集开始到最后一个任务结束，共花费 26.6ms
    • GC Workers：有 4 个线程负责垃圾收集，通过参数 -XX:ParallelGCThreads 设置，这个参数的值的设置，跟 CPU 有关，如果物理 CPU 支持的线程个数小于 8，则最多设置为 8；如果物理 CPU 支持的线程个数大于 8，则默认值为 number * 5/8
    • GC Worker Start：第一个垃圾收集线程开始工作时 JVM 启动后经过的时间（min）；最后一个垃圾收集线程开始工作时 JVM 启动后经过的时间（max）；diff 表示 min 和 max 之间的差值。理想情况下，你希望他们几乎是同时开始，即 diff 趋近于 0。
    • Ext Root Scanning：扫描 root 集合（线程栈、JNI、全局变量、系统表等等）花费的时间，扫描 root 集合是垃圾收集的起点，尝试找到是否有 root 集合中的节点指向当前的收集集合（CSet）

    • Update RS(Remembered Set or RSet)：每个分区都有自己的 RSet，用来记录其他分区指向当前分区的指针，如果 RSet 有更新，G1 中会有一个 post-write barrier 管理跨分区的引用——新的被引用的 card 会被标记为 dirty，并放入一个日志缓冲区，如果这个日志缓冲区满了会被加入到一个全局的缓冲区，在 JVM 运行的过程中还有线程在并发处理这个全局日志缓冲区的 dirty card。Update RS表示允许垃圾收集线程处理本次垃圾收集开始前没有处理好的日志缓冲区，这可以确保当前分区的 RSet 是最新的。

      • Processed Buffers，这表示在 Update RS 这个过程中处理多少个日志缓冲区。
    • Scan RS：扫描每个新生代分区的 RSet，找出有多少指向当前分区的引用来自 CSet。
    • Code Root Scanning：扫描代码中的 root 节点（局部变量）花费的时间
    • Object Copy：在疏散暂停期间，所有在 CSet 中的分区必须被转移疏散，Object Copy 就负责将当前分区中存活的对象拷贝到新的分区。

    • Termination：当一个垃圾收集线程完成任务时，它就会进入一个临界区，并尝试帮助其他垃圾线程完成任务（steal outstanding tasks），min 表示该垃圾收集线程什么时候尝试 terminatie，max 表示该垃圾收集回收线程什么时候真正 terminated。

      • Termination Attempts：如果一个垃圾收集线程成功盗取了其他线程的任务，那么它会再次盗取更多的任务或再次尝试 terminate，每次重新 terminate 的时候，这个数值就会增加。
    • GC Worker Other：垃圾收集线程在完成其他任务的时间
    • GC Worker Total：展示每个垃圾收集线程的最小、最大、平均、差值和总共时间。
    • GC Worker End：min 表示最早结束的垃圾收集线程结束时该 JVM 启动后的时间；max 表示最晚结束的垃圾收集线程结束时该 JVM 启动后的时间。理想情况下，你希望它们快速结束，并且最好是同一时间结束。

  3. 列出了新生代 GC 中的一些任务：

    • Code Root Fixup：释放用于管理并行垃圾收集活动的数据结构，应该接近于 0，该步骤是线性执行的；
    • Code Root Purge：清理更多的数据结构，应该很快，耗时接近于 0，也是线性执行。
    • Clear CT：清理 card table

  4. 包含一些扩展功能

    • Choose CSet：选择要进行回收的分区放入 CSet（G1 选择的标准是垃圾最多的分区优先，也就是存活对象率最低的分区优先）
    • Ref Proc：处理 Java 中的各种引用——soft、weak、final、phantom、JNI 等等。
    • Ref Enq：遍历所有的引用，将不能回收的放入 pending 列表
    • Redirty Card：在回收过程中被修改的 card 将会被重置为 dirty
    • Humongous Register：JDK8u60 提供了一个特性，巨型对象可以在新生代收集的时候被回收——通过 G1ReclaimDeadHumongousObjectsAtYoungGC 设置，默认为 true。
    • Humongous Reclaim：做下列任务的时间：确保巨型对象可以被回收、释放该巨型对象所占的分区，重置分区类型，并将分区还到 free 列表，并且更新空闲空间大小。
    • Free CSet：将要释放的分区还回到 free 列表。

  5. 展示了不同代的大小变化，以及堆大小的自适应调整。

    • Eden:1097.0M(1097.0M)->0.0B(967.0M)：（1）当前新生代收集触发的原因是 Eden 空间满了，分配了 1097M，使用了 1097M；（2）所有的 Eden 分区都被疏散处理了，在新生代结束后 Eden 分区的使用大小成为了 0.0B；（3）Eden 分区的大小缩小为 967.0M
    • Survivors:13.0M->139.0M：由于年轻代分区的回收处理，survivor 的空间从 13.0M 涨到 139.0M；
    • Heap:1694.4M(2048.0M)->736.3M(2048.0M)：（1）在本次垃圾收集活动开始的时候，堆空间整体使用量是 1694.4M，堆空间的最大值是 2048M；（2）在本次垃圾收集结束后，堆空间的使用量是 763.4M，最大值保持不变。

  6. 第 6 点展示了本次新生代垃圾收集的时间

    • user=0.8：垃圾收集线程在新生代垃圾收集过程中消耗的 CPU 时间，这个时间跟垃圾收集线程的个数有关，可能会比 real time 大很多；
    • sys=0.0：内核态线程消耗的 CPU 时间
      –real=0.03：本次垃圾收集真正消耗的时间；

并发垃圾收集

G1 的第二种收集活动是并发垃圾收集，并发垃圾收集的触发条件有很多，但是做的工作都相同，它的日志如下图所示：

  1. 标志着并发垃圾收集阶段的开始：

    • GC pause(G1 Evacuation Pause)(young)(initial-mark)：为了充分利用 STW 的机会来 trace 所有可达（存活）的对象，initial-mark 阶段是作为新生代垃圾收集中的一部分存在的（搭便车）。initial-mark 设置了两个 TAMS（top-at-mark-start）变量，用来区分存活的对象和在并发标记阶段新分配的对象。在 TAMS 之前的所有对象，在当前周期内都会被视作存活的。

  2. 表示第并发标记阶段做的第一个事情：根分区扫描

    • GC concurrent-root-region-scan-start：根分区扫描开始，根分区扫描主要扫描的是新的 survivor 分区，找到这些分区内的对象指向当前分区的引用，如果发现有引用，则做个记录；
    • GC concurrent-root-region-scan-end：根分区扫描结束，耗时 0.0030613s

  3. 表示并发标记阶段

    • GC Concurrent-mark-start：并发标记阶段开始。（1）并发标记阶段的线程是跟应用线程一起运行的，不会 STW，所以称为并发；并发标记阶段的垃圾收集线程，默认值是 Parallel Thread 个数的 25%，这个值也可以用参数 -XX:ConcGCThreads 设置；（2）trace 整个堆，并使用位图标记所有存活的对象，因为在 top TAMS 之前的对象是隐式存活的，所以这里只需要标记出那些在 top TAMS 之后、阈值之前的；（3）记录在并发标记阶段的变更，G1 这里使用了 SATB 算法，该算法要求在垃圾收集开始的时候给堆做一个快照，在垃圾收集过程中这个快照是不变的，但实际上肯定有些对象的引用会发生变化，这时候 G1 使用了 pre-write barrier 记录这种变更，并将这个记录存放在一个 SATB 缓冲区中，如果该缓冲区满了就会将它加入到一个全局的缓冲区，同时 G1 有一个线程在并行得处理这个全局缓冲区；（4）在并发标记过程中，会记录每个分区的存活对象占整个分区的大小的比率；
    • GC Concurrent-mark-end：并发标记阶段结束，耗时 0.3055438s

  4. 重新标记阶段，会 Stop the World

    • Finalize Marking：Finalizer 列表里的 Finalizer 对象处理，耗时 0.0014099s；
    • GC ref-proc：引用（soft、weak、final、phantom、JNI 等等）处理，耗时 0.0000480s；
    • Unloading：类卸载，耗时 0.0025840s；
    • 除了前面这几个事情，这个阶段最关键的结果是：绘制出当前并发周期中整个堆的最后面貌，剩余的 SATB 缓冲区会在这里被处理，所有存活的对象都会被标记；

  5. 清理阶段，也会 Stop the World

    • 计算出最后存活的对象：标记出 initial-mark 阶段后分配的对象；标记出至少有一个存活对象的分区；
    • 为下一个并发标记阶段做准备，previous 和 next 位图会被清理；
    • 没有存活对象的老年代分区和巨型对象分区会被释放和清理；
    • 处理没有任何存活对象的分区的 RSet；
    • 所有的老年代分区会按照自己的存活率（存活对象占整个分区大小的比例）进行排序，为后面的 CSet 选择过程做准备；

  6. 并发清理阶段

    • GC concurrent-cleanup-start：并发清理阶段启动。完成第 5 步剩余的清理工作；将完全清理好的分区加入到二级 free 列表，等待最终还会到总体的 free 列表；
    • GC concurrent-cleanup-end：并发清理阶段结束，耗时 0.0012954s

混合收集

在并发收集阶段结束后，你会看到混合收集阶段的日志，如下图所示，该日志的大部分跟之前讨论的新生代收集相同，只有第 1 部分不一样：GC pause(G1 Evacuation Pause)(mixed),0.0129474s，这一行表示这是一个混合垃圾收集周期；在混合垃圾收集处理的 CSet 不仅包括新生代的分区，还包括老年代分区——也就是并发标记阶段标记出来的那些老年代分区。

Full GC

如果堆内存空间不足以分配新的对象，或者是 Metasapce 空间使用率达到了设定的阈值，那么就会触发 Full GC——你在使用 G1 的时候应该尽量避免这种情况发生，因为 G1 的 Full Gc 是单线程、会 Stop The World，代价非常高。Full GC 的日志如下图所示，从中你可以看出三类信息

  1. Full GC 的原因，这个图里是 Allocation Failure，还有一个常见的原因是 Metadata GC Threshold；
  2. Full GC 发生的频率，每隔几天发生一次 Full GC 还可以接受，但是每隔 1 小时发生一次 Full GC 则不可接受；
  3. Full GC 的耗时，这张图里的 Full GC 耗时 150ms（PS：按照我的经验，实际运行中如果发生 Full GC，耗时会比这个多很多）

基础配置参数中，我这里还想介绍两个：-XX:+PrintGCApplicationStoppedTime和-XX:+PrintGCApplicationConcurrentTime，这两个参数也可以为你提供有用的信息，如下图所示：

  1. 记录了应用线程在安全点被暂停的总时间（也就是 STW 的总时间）
  2. 记录了让所有应用线程进入安全点所花费的总时间
  3. 记录了在两个安全点之间应用线程运行的时间

总结

这篇文章只是翻译了原文的第一部分，基础参数篇，我接下来会有一篇或两篇文章完成原文的高级参数和 Debug 参数两部分。——

本号专注于后端技术、JVM 问题排查和优化、Java 面试题、个人成长和自我管理等主题，为读者提供一线开发者的工作和成长经验，期待你能在这里有所收获。

退出移动版