三谈 GC: GC 算法实现和日志

笔者在 浅谈 JAVA 中的垃圾回收机制 和 二谈 GC：从分区到 GC 事件 这两篇文章中，分别从比较理论性的角度、分区分代机制和 GC 事件对 GC 机制进行了阐述分析。本篇笔者从 GC 算法实现的角度进一步对此系列进行延续。

GC 算法概览

对于大多数 JVM 来说，需要两种不同的 GC 算法：一种用于清除 Young Generation，另一种用于清除 Old Generation。我们可以从内嵌到 JVM 中的各种算法中进行选择，如果不显式指定垃圾收集算法，则将使用特定于平台的默认算法。下面是基于 JDK8 的一个备忘单，对于较老的 Java 版本，可用的组合可能会有一点不同：

上面表格中加粗显示的四种组合是重点关注的，其余的要么已被弃用，要么不受支持，要么无法在现实世界中应用。因此，在下面的介绍中，将着重看依赖几个组合的工作原理：

• • Young Generation 和 Old Generation 的串行 GC

• • Young Generation 和 Old Generation 的并行 GC

• • 并行 Young Generation GC + CMS

• • G1 包含了 Young Generation 和 Old Generation 的集合

Serial GC

串行垃圾收集器收集对年轻代使用 mark-copy，对老代使用 mark-sweep-compact。顾名思义，这两个收集器都是单线程收集器，无法并行处理手头的任务。这两种收集器还会触发 stop-the-world 暂停，停止所有应用程序线程。

因此，这种 GC 算法不能利用现代硬件中常见的多 CPU 核，与可用核数无关，JVM 在垃圾收集期间只使用一个核。

可以通过在 JVM 启动脚本中指定参数，为 Young Generation 和 Old Generation 启用这个收集器：

java -XX:+UseSerialGC com.xx.xx

这种收集器存在也有它的意义，比如适用于堆大小为几百兆字节、运行在单一 CPU 环境中的 JVM 上。对于大多数服务器端部署来说，这种组合基本不会出现。大多数服务器端部署都是在具有多个内核的平台上完成的，这意味着通过选择串行 GC，就人为地限制了系统资源的使用，这会导致很多资源处于空闲状态，没有办法得到充分利用；如果这些闲置的资源被利用起来，从一定程度上讲，可以减少系统延迟或增加系统吞吐量。

下面看下串行 GC 时垃圾收集器日志是什么样的，以及可以从中获得哪些有用的信息。这里使用以下参数在 JVM 上打开 GC 日志记录：-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps

结果输出类似如下

2024-07-01T14:45:37.987-0200:151.126:[GC (AllocationFailure)151.126:[DefNew:
629119K->69888K(629120K),0.0584157 secs]1619346K->1273247K(2027264K),0.0585007 secs]
[Times: user=0.06 sys=0.00, real=0.06 secs]
2024-07-01T14:45:59.690-0200:172.829:[GC (AllocationFailure)172.829:[DefNew:
629120K->629120K(629120K),0.0000372 secs]172.829:[Tenured:1203359K-
>755802K(1398144K),0.1855567 secs]1832479K->755802K(2027264K),[Metaspace:6741K-
>6741K(1056768K)],0.1856954 secs][Times: user=0.18 sys=0.00, real=0.18 secs]

GC 日志中的这一小段代码展示了大量关于 JVM 内部发生的事情的信息。事实上，在这个片段中发生了两个 GC 事件，一个清理 Young Generation，另一个处理整个堆。

Minor GC

以下代码片段包含了清理年轻代的 GC 事件的信息:

2024-07-01T14:45:37.987-02001:151.1262:[GC3(AllocationFailure4)151.126:[DefNew5:629119K->69888K6(629120K)7,0.0584157 secs]1619346K->1273247K8(2027264K)9,0.0585007 secs10][Times: user=0.06 sys=0.00, real=0.06 secs]11

1.2024-07-01T14:45:37.987-0200- GC 发生的时间
2.151.126– GC 事件启动的时间，相对于 JVM 启动时间，以秒为单位来衡量。
3.  GC –标记区分Minor GC和Full GC，这里它表明这是一个Minor GC。
4.AllocationFailure–收集的原因，这里指的是分配失败
5.DefNew–所使用的垃圾收集器的名称。这个名称代表用于清理年轻代的单线程标记-复制 STW 垃圾收集器。
6.629119K->69888K–在收集前后使用年轻代空间
7.(629120K)–年轻代总空间
8.1619346K->1273247K–收集之前和之后使用的堆的总大小。
9.(2027264K)–堆可用总大小.
10.0.0585007 secs – GC 事件持续时间(以秒为单位)。
11.[Times: user=0.06 sys=0.00, real=0.06 secs]- GC 事件持续时间，以不同类别衡量:

-   user -垃圾收集器线程在此收集期间消耗的总 CPU 时间
-   sys -在操作系统调用或等待系统事件时花费的时间
-   real - 应用程序停止的实时时间。由于串行垃圾收集器总是只使用一个线程，因此实时等于用户和系统时间的总和。

从上面的片段中，我们可以确切地了解在 GC 事件期间 JVM 内的内存消耗发生了什么。在此收集之前，堆使用总量为 1,619,346 K。其中，年轻代消费了 629119 K。由此我们可以计算出年老代的使用量等于 99022K。

在下一批数字中隐藏着一个更重要的结论，在收集之后，年轻代的使用量减少了 559,231K，但总的堆使用量只减少了 346,099K。由此我们可以再次得出，有 213,132K 的对象从年轻代提升到了年老代。

这个 GC 事件还显示了以下快照，显示了 GC 启动前和结束后的内存使用情况：

Full GC

在理解了第一个 Minor GC 事件之后，再看看日志中的第二个 GC 事件:

   2024-07-01T14:45:59.690-02001:172.8292:[GC (AllocationFailure)172.829:[DefNew:
629120K->629120K(629120K),0.0000372 secs3]172.829:[Tenured4:1203359K->755802K
5(1398144K)6,0.1855567 secs7]1832479K->755802K8(2027264K)9,[Metaspace:6741K-
>6741K(1056768K)]10[Times: user=0.18 sys=0.00, real=0.18 secs]11

2024-07-01T14:45:59.690-0200– GC事件启动时间。
172.829– GC事件启动的时间，相对于JVM启动时间。以秒为单位来衡量。
[DefNew:629120K->629120K(629120K),0.0000372 secs –0.0000372秒-类似于前面的例子，在这个事件中，由于分配失败，在年轻代中发生了一次Minor GC。对于这个收集，与之前一样运行相同的DefNew收集器，它将年轻代的使用量从629120K减少到0。请注意，由于错误的行为，JVM 不正确地报告了这一点，而是报告年轻代已经完全满了。这个收集花费了0.0000372秒。
Tenured–用于清理年老代的垃圾收集器的名称。Tenured名称表示使用的是单线程的 stop-the-world mark-sweep-compact 垃圾收集器。
1203359K->755802K–在事件前后年老代大小。
(1398144K)–年老代总大小
0.1855567 secs –清除老代所需的时间。
1832479K->755802K–在收集年轻代和年老代之前和之后使用整个堆情况。
(2027264K)– JVM可用的堆总大小。
[Metaspace:6741K->6741K(1056768K)]–元空间收集的信息。可以看到，在事件期间没有在元空间中收集垃圾。
[Times: user=0.18 sys=0.00, real=0.18 secs]– GC事件的持续时间，在不同类别中测量（同上，分为 user sys 和 real）

与 Minor GC 的区别是明显的，除了年轻代，在这个 GC 事件中，年老代和元空间也被清理。事件前后的内存布局大致如下图所示:

Parallel GC

这种垃圾收集器组合在年轻代中使用 mark-copy，在年老代中使用 mark-clean-compact。年轻代和年老代的收集都会触发 STW 事件，停止所有应用程序线程来执行垃圾收集。这两个收集器都使用多个线程运行 mark 和 copy/compact 阶段，因此称为“并行”。使用这种方法，收集时间可以大大减少。

垃圾收集过程中使用的线程数可以通过命令行参数 -XX:ParallelGCThreads=X 进行配置。X 默认值等于机器的核数。并行 GC 的选择是通过在 JVM 启动脚本中指定以下任意参数组合来完成：

java -XX:+UseParallelGC xxx
java -XX:+UseParallelOldGC xxx
java -XX:+UseParallelGC -XX:+UseParallelOldGC xxx

当你的主要目标是增加吞吐量时，并行垃圾收集器适用于多核机器。更高的吞吐量是由于更有效地使用系统资源：

• • 在收集期间，所有的内核都在并行地清理垃圾，从而导致更短的暂停时间

• • 在垃圾收集周期之间，两个收集器都不会消耗任何资源

另一方面，由于收集的所有阶段都必须在没有任何中断的情况下进行，因此这些收集器仍然容易受到应用程序线程停止期间的长时间暂停的影响。因此，如果延迟是你的主要目标，那么则需要慎重考虑下。

现在让我们回顾一下使用并行 GC 时垃圾收集器日志的样子，以及可以从中获得哪些有用的信息。为此，这里再次查看垃圾收集器的日志，这些日志再次暴露了一个 Minor GC 的和一个 Major GC 暂停：

2024-07-01T14:27:40.915-0200:116.115:[GC (AllocationFailure)[PSYoungGen:2694440K->1305132K(2796544K)]9556775K->8438926K(11185152K),0.2406675 secs][Times: user=1.77 sys=0.01, real=0.24 secs]
2024-07-01T14:27:41.155-0200:116.356:[Full GC (Ergonomics)[PSYoungGen:1305132K->0K(2796544K)][ParOldGen:7133794K->6597672K(8388608K)]8438926K->6597672K(11185152K),[Metaspace:6745K->6745K(1056768K)],0.9158801 secs][Times: user=4.49 sys=0.64, real=0.92 secs]

Minor GC

两个事件中的第一个表示发生在年轻代中的 GC 事件：

2024-07-01T14:27:40.915-02001:116.1152:[GC3(AllocationFailure4)
[PSYoungGen5:2694440K->1305132K6(2796544K)7]9556775K->8438926K8(11185152K)9,0.2406675
secs10][Times: user=1.77 sys=0.01, real=0.24 secs]11

1.2024-07-01T14:27:40.915-0200– GC事件启动的时间。
2.116.115– GC事件启动的时间，相对于JVM启动时间。以秒为单位来衡量。
3.  GC –标记区分Minor GC和Full GC，这里它表明这是一个MinorGC。
4.AllocationFailure–收集原因，分配失败
5.PSYoungGen–所使用的垃圾收集器的名称，表示用于清理年轻代的并行标记-复制（STW）垃圾收集器。
6.2694440K->1305132K–在收集前后使用年轻代情况
7.(2796544K)–年轻代总大小
8.9556775K->8438926K–收集之前和之后的堆使用总量
9.(11185152K)–总可用堆
10.0.2406675 secs – GC事件持续时间(以秒为单位)
11.[Times: user=1.77 sys=0.01, real=0.24 secs]– 同上

因此，收集之前的总堆消耗是 9,556,775K。在年轻代中，有 2694440 K。这意味着使用的年老代是 6862335 K。在收集之后，年轻代的使用量减少了 1,389,308K，但是总的堆使用量只减少了 1,117,849K。这意味着 271,459K 由年轻代代晋升为年老代。

Full GC

下面再看下 Full GC

2024-07-01T14:27:41.155-02001:116.3562:[Full GC3 (Ergonomics4)[PSYoungGen:1305132K->0K(2796544K)]5[ParOldGen6:7133794K->6597672K7(8388608K)8]8438926K->6597672K9(11185152K)10,[Metaspace:6745K->6745K(1056768K)]11,0.9158801 secs12,[Times: user=4.49 sys=0.64, real=0.92 secs]13

1.2024-07-01T14:27:41.155-0200–Timewhen the GC event started
2.116.356–Timewhen the GC event started, relative to the JVM startup time.Measuredin seconds.Inthiscase we can see the event started right after the previous Minor GC finished.
3.Full GC –标志，表明事件是正在清除年轻代和年老代的Full GC 事件。
4.Ergonomics– GC发生的原因。这表明 JVM 内部人机工程学决定现在是收集一些垃圾的合适时机。
5.[PSYoungGen:1305132K->0K(2796544K)]–与前面的示例类似，使用名为“PSYoungGen”的并行标记-复制(STW)垃圾收集器来清理年轻代。年轻代的使用从1305132K减少到0，这是Full GC 的典型结果。
6.ParOldGen–用于清理年老代的收集器的类型。在本例中，使用了名为ParOldGen的并行标记-清除-压缩停止（STW）收集器。
7.7133794K->6597672K–在收集前后使用年老代情况
8.(8388608K)–年老代的总大小
9.8438926K->6597672K–在收集之前和之后使用整个堆情况
10.(11185152K)–可用堆总大小
11.[Metaspace:6745K->6745K(1056768K)]–关于元空间区域的类似信息。正如我们所看到的，在这个事件期间，元空间中没有收集垃圾。
12.0.9158801 secs – GC 执行持续时间

同样，与 Minor GC 有比较明显的区别是，除了年轻代之外，在这个 GC 事件中还清理了年老代和元空间。事件前后的内存布局如下图所示：

Concurrent Mark and Sweep

这种垃圾收集器的官方名称是“并发标记和清除垃圾收集器-CMS”，该算法在年轻代中采用并行的 STW mark-copy 算法，在年老代中采用并行的 mark-clean 算法。

这个收集器的设计是为了避免在年老代中收集时出现长时间的暂停。它通过两种方法来实现这一点，

• • 1、没有压缩年老代，而是使用 *Free List* 来管理回收的空间

• • 2、在 mark 和 clean 阶段与应用程序并行工作，这意味着垃圾收集并没有显式地停止应用程序线程来执行这些阶段。

但是，这些过程仍然要与应用程序线程竞争 CPU 的时间。默认情况下，CMS 算法使用的线程数等于机器物理内核数的 ¼。可以通过在命令行中指定以下选项来选择:

java -XX:+UseConcMarkSweepGC xxx

如果你的主要目标是延迟，那么这种组合在多核机器上是一个很好的选择。减少单个 GC 暂停的持续时间将直接影响最终用户对应用程序的感知方式，让他们感觉应用程序的响应速度更快。在大多数情况下，至少有一些 CPU 资源是由 GC 消耗的，而不是执行应用程序的代码，所以在 CPU 限制的应用程序中，CMS 的吞吐量通常比并行 GC 差。

PS: CMS 虽然说是延迟优先的一种算法实现，但是它并不能保证延迟时间可控，当有大量对象需要进行回收时，还是可能会导致较长的停顿时间。

这里也看看 CMS 算法是如何在实践中应用的：

2024-07-01T16:23:07.219-0200:64.322:[GC (AllocationFailure)64.322:[ParNew:613404K->68068K(613440K),0.1020465 secs]10885349K->10880154K(12514816K),0.1021309 secs][Times: user=0.78 sys=0.01, real=0.11 secs]
2024-07-01T16:23:07.321-0200:64.425:[GC (CMS InitialMark)[1 CMS-initial-mark:10812086K(11901376K)]10887844K(12514816K),0.0001997 secs][Times: user=0.00 sys=0.00, real=0.00 secs]
2024-07-01T16:23:07.321-0200:64.425:[CMS-concurrent-mark-start]
2024-07-01T16:23:07.357-0200:64.460:[CMS-concurrent-mark:0.035/0.035 secs][Times: user=0.07 sys=0.00, real=0.03 secs]
2024-07-01T16:23:07.357-0200:64.460:[CMS-concurrent-preclean-start]
2024-07-01T16:23:07.373-0200:64.476:[CMS-concurrent-preclean:0.016/0.016 secs][Times: user=0.02 sys=0.00, real=0.02 secs]
2024-07-01T16:23:07.373-0200:64.476:[CMS-concurrent-abortable-preclean-start]
2024-07-01T16:23:08.446-0200:65.550:[CMS-concurrent-abortable-preclean:0.167/1.074 secs][Times: user=0.20 sys=0.00, real=1.07 secs]
2024-07-01T16:23:08.447-0200:65.550:[GC (CMS FinalRemark)[YG occupancy:387920 K (613440 K)]65.550:[Rescan(parallel),0.0085125 secs]65.559:[weak refs processing,0.0000243 secs]65.559:[class unloading,0.0013120 secs]65.560:[scrub symbol table,0.0008345 secs]65.561:[scrub string table,0.0001759 secs][1 CMS-remark:10812086K(11901376K)]11200006K(12514816K),0.0110730 secs][Times: user=0.06 sys=0.00, real=0.01 secs]
2024-07-01T16:23:08.458-0200:65.561:[CMS-concurrent-sweep-start]
2024-07-01T16:23:08.485-0200:65.588:[CMS-concurrent-sweep:0.027/0.027 secs][Times: user=0.03 sys=0.00, real=0.03 secs]
2024-07-01T16:23:08.485-0200:65.589:[CMS-concurrent-reset-start]
2024-07-01T16:23:08.497-0200:65.601:[CMS-concurrent-reset:0.012/0.012 secs][Times: user=0.01 sys=0.00, real=0.01 secs]

Minor GC

2024-07-01T16:23:07.219-02001: 64.3222:[GC3(Allocation Failure4) 64.322: [ParNew5: 613404K->68068K6(613440K) 7, 0.1020465 secs8] 10885349K->10880154K 9(12514816K)10, 0.1021309 secs11][Times: user=0.78 sys=0.01, real=0.11 secs]12

这里和前面的差别不大，不单独解释。

从上面可以看到，在收集之前，总使用堆为 10,885,349K，使用的年轻代共享为 613,404K。这意味着年老代的是 10,271,945K。收集之后，年轻代的使用量减少了 545336k，但总堆使用量只减少了 5195k。这意味着 540141k 从年轻代晋升为年老代。

Full GC

CMS收集器的整个事件如下所示:

2024-07-01T16:23:07.321-0200:64.425:[GC (CMS InitialMark)[1 CMS-initial-mark:10812086K(11901376K)]10887844K(12514816K),0.0001997 secs][Times: user=0.00 sys=0.00, real=0.00 secs]
2024-07-01T16:23:07.321-0200:64.425:[CMS-concurrent-mark-start]
2024-07-01T16:23:07.357-0200:64.460:[CMS-concurrent-mark:0.035/0.035 secs][Times: user=0.07 sys=0.00, real=0.03 secs]
2024-07-01T16:23:07.357-0200:64.460:[CMS-concurrent-preclean-start]
2024-07-01T16:23:07.373-0200:64.476:[CMS-concurrent-preclean:0.016/0.016 secs][Times: user=0.02 sys=0.00, real=0.02 secs]
2024-07-01T16:23:07.373-0200:64.476:[CMS-concurrent-abortable-preclean-start]
2024-07-01T16:23:08.446-0200:65.550:[CMS-concurrent-abortable-preclean:0.167/1.074 secs][Times: user=0.20 sys=0.00, real=1.07 secs]
2024-07-01T16:23:08.447-0200:65.550:[GC (CMS FinalRemark)[YG occupancy:387920 K (613440 K)]65.550:[Rescan(parallel),0.0085125 secs]65.559:[weak refs processing,0.0000243 secs]65.559:[class unloading,0.0013120 secs]65.560:[scrub symbol table,0.0008345 secs]65.561:[scrub string table,0.0001759 secs][1 CMS-remark:10812086K(11901376K)]11200006K(12514816K),0.0110730 secs][Times: user=0.06 sys=0.00, real=0.01 secs]
2024-07-01T16:23:08.458-0200:65.561:[CMS-concurrent-sweep-start]
2024-07-01T16:23:08.485-0200:65.588:[CMS-concurrent-sweep:0.027/0.027 secs][Times: user=0.03 sys=0.00, real=0.03 secs]
2024-07-01T16:23:08.485-0200:65.589:[CMS-concurrent-reset-start]
2024-07-01T16:23:08.497-0200:65.601:[CMS-concurrent-reset:0.012/0.012 secs][Times: user=0.01 sys=0.00, real=0.01 secs]

在实际情况中，在同时收集年老代的过程中，年轻代的 Minor GC 随时都可能发生。在这种情况下，下面看到的 major collection 记录与前一节中讨论的 Minor GC 事件混杂在一起了。

阶段 1：Initial Mark

初始标记是 CMS 期间的两个 STW 事件中的一个。此阶段的目标是标记年老代的所有对象，这些对象要么是直接的 GC 根，要么是从年轻代中的某个活动对象引用的。后者很重要，因为年老代是单独收集的。

2024-07-01T16:23:07.321-0200:64.421:[GC (CMS InitialMark2[1 CMS-initial-
mark:10812086K3(11901376K)4]10887844K5(12514816K)6,0.0001997 secs][Times: user=0.00
sys=0.00, real=0.00 secs]7

1.2024-07-01T16:23:07.321-0200:64.42– GC 事件启动的时间，包括时钟时间和相对于JVM 启动的时间。对于接下来的阶段，在整个事件中都使用相同的概念。
2.  CMS InitialMark–收集阶段(此处为“初始标记”)，即收集所有 GC 根。
3.10812086K–当前OldGeneration内存使用情况.
4.(11901376K)–年老代中的总可用内存。
5.10887844K–当前使用的堆情况
6.(12514816K)–总可用对大小
7.0.0001997 secs][Times: user=0.00 sys=0.00, real=0.00 secs]–阶段的持续时间，也可以在user 、sys 和 real 中测量。

阶段 2 ：Concurrent Mark

并发标记阶段，垃圾收集器将遍历年老代并标记所有活动对象，从“初始标记”前一阶段中找到的 GC 根开始。“并发标记”阶段，顾名思义，它与应用程序同时运行，不会停止应用程序线程。但是，并不是年老代中的所有活动对象都可以被标记，因为应用程序在标记期间会改变引用（可能会有 Minor GC 的发生，这里涉及到我在前两篇文章中提到的三色标记算法）。

在插图中，一个指向“当前对象”的参考点与标记线程同时被移除。

2024-07-01T16:23:07.321-0200:64.425:[CMS-concurrent-mark-start]

2024-07-01T16:23:07.357-0200:64.460:[CMS-concurrent-mark1:035/0.035 secs2][Times: user=0.07 sys=0.00, real=0.03 secs]3

1.  CMS-concurrent-mark –收集阶段——此处为“并发标记”——遍历年老代并标记所有活动对象。
2.035/0.035 secs –相位的持续时间，相应地显示流逝时间和挂钟时间。
3.[Times: user=0.07 sys=0.00, real=0.03 secs]– “时间”部分对于并发标记阶段来说没那么有意义，因为它是从并发标记开始度量的，并且不仅仅包括为并发标记所做的工作。

阶段 3：Concurrent Preclean

这也是一个并发阶段，与应用程序线程并行运行。当前一阶段与应用程序同时运行时，一些引用发生了更改。当发生这种情况时，JVM 将包含变化对象的堆区域(称为“Card”)标记为“脏”(这称为卡片标记)，Card 是典型的采用空间换时间的逻辑，因为不需要扫描整个Heap 空间，从而可以有效的降低 GC 耗时。

在预清理阶段，这些脏对象会被计算在内，并且还会标记从这些脏对象可以到达的对象。这一步完成后，卡片将被清洗。

此外，这里还为最后的 重新标记 阶段执行了一些必要的准备工作。

2024-07-01T16:23:07.357-0200:64.460:[CMS-concurrent-preclean-start]

2024-07-01T16:23:07.373-0200:64.476:[CMS-concurrent-preclean1:0.016/0.016 secs2][Times: user=0.02 sys=0.00, real=0.02 secs]3

1.  CMS-concurrent-preclean –收集阶段–“并发预清理”，主要考虑在前一个标记阶段更改的引用。
2.0.016/0.016 secs –同上
3.[Times: user=0.02 sys=0.00, real=0.02 secs]– 同上

阶段 4：Concurrent Abortable Preclean

同样，并发阶段不会停止应用程序的线程。这个阶段的确切持续时间取决于许多因素，例如迭代的次数、完成的有效任务的数量、经过的时间等。

2024-07-01T16:23:07.373-0200:64.476:[CMS-concurrent-abortable-preclean-start]

2024-07-01T16:23:08.446-0200:65.550:[CMS-concurrent-abortable-preclean1:0.167/1.074 secs2][Times: user=0.20 sys=0.00, real=1.07 secs]3

1.  CMS-concurrent-abortable-preclean –收集阶段，并发可终止的预清理
2.0.167/1.074 secs –相位持续时间，分别显示流逝时间和挂钟时间。有意思的是，报告的用户时间要比时钟时间小得多。通常我们看到实时时间比用户时间短，也就意味着一些工作是并行完成的，因此经过的时钟时间比使用的 CPU 时间短。这里有少量的工作——0.167秒的 CPU 时间，垃圾收集器线程做了大量的等待。从本质上说，他们试图在必须暂停 STW 之前尽可能长时间地避开。默认情况下，此阶段最多可持续5 秒钟。

这一阶段可能会显著影响 “STW” 暂停的持续时间。

阶段 5：Final Remark

CMS 的第二个 STW 事件。这个 STW 阶段的目标是完成对年老代所有活动对象的标记。由于以前的 preclean 阶段是并发的，它们可能无法跟上应用程序的变化速度。为了完成这个工作，所以必须再次进行 STW。

通常，CMS 会尝试在 Young Generation 尽可能空的时候运行 Final Remark 阶段，以消除可能出现的多个 STW 相继发生的可能性。

下面是部分 GC 日志及说明：

2024-07-01T16:23:08.447-0200:65.5501:[GC (CMS FinalRemark2)[YG occupancy:387920 K (613440 K)3]65.550:[Rescan(parallel),0.0085125 secs]465.559:[weak refs processing,0.0000243 secs]65.5595:[class unloading,0.0013120 secs]65.5606:[scrub string table,0.0001759 secs7][1 CMS-remark:10812086K(11901376K)8]11200006K(12514816K)9,0.0110730 secs10][[Times: user=0.06 sys=0.00, real=0.01 secs]11

1.2024-07-01T16:23:08.447-0200:65.550–GC事件启动的时间，包括时钟时间和相对于JVM启动时间的时间。
2.  CMS FinalRemark–收集阶段–最终重新标记–标记了年老代中的所有活动对象，包括在先前的并发标记阶段中创建/修改的引用。
3.  YG occupancy:387920 K (613440 K)–年轻代占用和容量
4.[Rescan(parallel),0.0085125 secs]–“重新扫描”在应用程序停止时完成活动对象的标记。在本例中，重新扫描是并行进行的，耗时0.0085125秒。
5.  weak refs processing,0.0000243 secs]65.559–第一个子阶段，正在处理弱引用以及该阶段的持续时间和时间戳。
6.class unloading,0.0013120 secs]65.560–下一个子阶段，正在卸载未使用的类，并带有该阶段的持续时间和时间戳。
7.  scrub string table,0.0001759 secs –最后一个子阶段，清理符号和字符串表，它们分别保存了类级别的元数据和字符串内部池，暂停的时钟时间也包括在内。
8.10812086K(11901376K)–年老代情况
9.11200006K(12514816K)–堆使用情况
10.0.0110730 secs – 持续时间

在五个标记阶段之后，年老代的所有活对象都被标记，现在垃圾收集器将通过清除年老代来回收所有未引用的对象

阶段 6：Concurrent Sweep

与应用程序同时执行，不需要 STW。阶段的目的是删除未使用的对象，并回收它们所占用的空间以供将来使用。

阶段 7：Concurrent Reset

并行执行阶段，重置 CMS 算法的内部数据结构，并为下一个周期做好准备。

小结

总而言之，CMS 垃圾收集器通过将大量工作分摊到不需要停止应用程序的并发线程上，在减少暂停时间方面做得很好。但是，它也有一些缺点，最明显的是年老代碎片，并且在某些情况下（尤其是在大堆上），暂停持续时间缺乏可预测性。

G1 – Garbage First

G1 的一个关键设计目标是使得前面垃圾收集算法中导致的停机时间和分布变得可预测和可配置。事实上，G1 是一个软实时垃圾收集器，这意味着可以通过参数配置来设置特定的性能目标。

为了实现这个目标，G1 需要收集很多额外的洞察指标信息。首先，堆不必分割为连续的年轻代和年老代。相反，堆被分成若干个(通常是2048个)较小的堆区域（regions），这些区域可以存放对象。每个区域可以是 Eden 区、Survivor 或 Old regions。所有 Eden 和 Survivor 区的逻辑结合是年轻代，所有 Old regions 放在一起就是年老代：

这种分区使的 GC 可以避免一次收集整个堆，而是逐步解决问题：一次只考虑区域的一个子集，称为 Collection Set。在每个暂停期间都会收集所有 Young 区域，但也可能包括一些 Old 区域：

G1 的另一个新颖之处在于，它在并发阶段估计每个区域包含的实时数据量，用于构建 collection set，首先收集包含垃圾最多的区域。因此称它为： garbage-first collection。

启用 G1 收集器的情况下运行 JVM java -XX:+UseG1GC xxxx

Evacuation Pause: Fully Young（疏散停顿）

这个在前面的文章中也有提到过。在应用生命周期的开始阶段，G1 没有任何来自尚未执行的并发阶段的额外信息，所以它最初是在 Fully Young 模式下运行的。当年轻代填满时，应用程序线停止，并将 Young 区内的实时数据复制到 Survivor 区。

复制这些的过程叫做 Evacuation，它的工作方式和我们之前见过的其他年轻代的收集器差不多。Evacuation pauses 的完整日志相当大， 下面笔者给出一个小的片段：

0.134: [GC pause (G1 EvacuationPause)(young),0.0144119 secs]1

[ParallelTime:13.9 ms, GC Workers:8]2

…3

[CodeRootFixup:0.0 ms]4

[CodeRootPurge:0.0 ms]5

`[Clear CT: 0.1 ms]`

[Other:0.4 ms]6

…7

[Eden:24.0M(24.0M)->0.0B(13.0M)8Survivors:0.0B->3072.0K9Heap:24.0M(256.0M)->21.9M(256.0M)]10

[Times: user=0.04 sys=0.04, real=0.02 secs]11

1.0.134:[GC pause (G1 EvacuationPause)(young),0.0144119 secs]– G1 pause cleaning only (young) regions.暂停在 JVM 启动后134ms启动，暂停时间为以挂钟时间计算的0.0144秒。
2.[ParallelTime:13.9 ms, GC Workers:8]–表明在13.9 ms(实时)时间内，以下活动由8个线程并行执行
3.…–...
4.[CodeRootFixup:0.0 ms]–释放用于管理并行活动的数据结构，应该总是接近于零，按顺序完成。
5.[CodeRootPurge:0.0 ms]–清理更多的数据结构，也应该非常快，但不一定几乎为零。按顺序完成。
6.[Other:0.4 ms]–其他各种各样的活动
7.…–...
8.[Eden:24.0M(24.0M)->0.0B(13.0M)–暂停前后Eden区使用和容量情况
9.Survivors:0.0B->3072.0K–暂停前后Survivor区使用情况
10.Heap:24.0M(256.0M)->21.9M(256.0M)]– 暂停前后堆使用和容量情况

大部分繁重的工作是由多个专用 GC 工作线程完成的。可以看下下面的这段日志:

[Parallel Time:13.9 ms, GC Workers:8]1

[GC WorkerStart(ms)2`: Min: 134.0, Avg: 134.1, Max: 134.1, Diff: 0.1]`

[ExtRootScanning(ms)3`: Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 1.2]`

`[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]`

`[Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]`

`[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]`

[CodeRootScanning(ms)4`: Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.2]`

[ObjectCopy(ms)5`: Min: 10.8, Avg: 12.1, Max: 12.6, Diff: 1.9, Sum: 96.5]`

[Termination(ms)6`: Min: 0.8, Avg: 1.5, Max: 2.8, Diff: 1.9, Sum: 12.2]`

[TerminationAttempts7`: Min: 173, Avg: 293.2, Max: 362, Diff: 189, Sum: 2346]`

[GC WorkerOther(ms)8`: Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]`

    GC WorkerTotal(ms)9`: Min: 13.7, Avg: 13.8, Max: 13.8, Diff: 0.1, Sum: 110.2]`

[GC WorkerEnd(ms)10:Min:147.8,Avg:147.8,Max:147.8,Diff:0.0]

1.[ParallelTime:13.9 ms, GC Workers:8]–表示在13.9 ms(时钟时间)内，以下活动由8个线程并行执行
2.[GC WorkerStart(ms)–工作线程开始活动的时间点，与暂停开始时的时间戳相匹配。如果Min和Max相差很大，那么这可能表明使用了太多的线程，或者机器上的其他进程正在从JVM中的垃圾收集进程窃取CPU时间
3.[ExtRootScanning(ms)–扫描外部（非堆）根目录（例如类加载器，JNI引用，JVM系统根目录等）所花的时间。显示经过的时间，“Sum”是CPU时间
4.[CodeRootScanning(ms)–扫描来自实际代码的根需要多长时间:本地变量等。
5.[ObjectCopy(ms)–从收集区域复制活动对象所需的时间。
6.[Termination(ms)–工作线程需要多长时间才能确保它们可以安全地停止并且没有更多的工作要做，然后实际终止
7.[TerminationAttempts–工作者线程尝试尝试终止多少次。如果工人发现实际上还有更多工作要做，并且为时过早，则尝试失败。
8.[GC WorkerOther(ms)–其他杂项小活动，在日志中不应单独列出。
9.  GC WorkerTotal(ms)–工作者线程总共工作了多长时间
10.[GC WorkerEnd(ms)– 工作线程完成工作的时间

此外，Evacuation pause 期间还会执行一些其他活动

[Other:0.4 ms]1

`[Choose CSet: 0.0 ms]`

[RefProc:0.2 ms]2

[RefEnq:0.0 ms]3

`[Redirty Cards: 0.1 ms]`

`[Humongous Register: 0.0 ms]`

`[Humongous Reclaim: 0.0 ms]`

[FreeCSet:0.0 ms]4

1.[Other:0.4 ms]–其他活动，其中许多活动也并行进行
2.[RefProc:0.2 ms]–处理非强引用的时间：清除它们或确定不需要清除。
3.[RefEnq:0.0 ms]–将剩余的非强引用排队到适当的ReferenceQueue所花费的时间
4.[FreeCSet:0.0 ms]–返回 GC 集中的释放区域以使它们可用于新分配所花费的时间。

Concurrent Marking

G1 收集器其实是在 CMS 的很多概念的基础上演化来的，因此在并发标记的目标上非常相似。G1 并发标记使用 Snapshot-At-The-Beginning（SATB） 方法，标记所有在标记周期开始时处于活动状态的对象，即使这些对象同时已经变成了垃圾。

当堆的总体占用量足够大时，开始并发标记。默认情况下，它是 45%，但是可以通过InitiatingHeapOccupancyPercent JVM 参数进行更改。与 CMS一样，G1 中的并发标记由许多阶段组成，其中一些阶段是完全并发的，有些阶段则需要停止应用程序线程。

阶段 1： Initial Mark

这个阶段标记了所有可以从 GC 根直接访问的对象。在 CMS 中，它会触发 STW 事件，但在 G1 中，依托于疏散停顿模型，它的开销会减少很多。下面是一个典型的 GC 日志:

1.631: [GC pause (G1 Evacuation Pause) (young) **(initial-mark)** , 0.0062656 secs]

阶段 2：Root Region Scan

这个阶段标记了所有可以从所谓的根区域到达的活动对象，即那些不是空的并且可能最终不得不在标记周期的中间收集的活动对象。由于在并发标记的中间移动东西会引起问题，因此必须在下一个疏散停顿开始之前完成此阶段。

1.362: [GC concurrent-root-region-scan-start]
1.364: [GC concurrent-root-region-scan-end, 0.0028513 secs]

阶段 3：Concurrent Mark

这个阶段和 CMS 非常相似，它只是遍历对象图，并在特殊的位图中标记访问的对象。为了确保满足 snapshot-at-the beginning 的语义，G1 GC 要求应用程序线程对对象图进行的所有并发更新都应保留先前的已知标记信息。

这是通过使用 Pre-Write barriers来实现的。Pre-Write barriers是每当在 G1 并发标记处于活动状态并写入字段时，将先前的 referee 存储在日志缓冲区中，以供并发标记线程处理。

1.364: [GC concurrent-mark-start]
1.645: [GC concurrent-mark-end, 0.2803470 secs]

阶段 4：Remark

和先前在 CMS 中的一样，这里的 remark 也会触发一个 STW 事件，这个阶段将完成标记过程。对于 G1，它短暂地停止了应用程序线程以停止并发更新日志的流入，并处理了剩余的少量日志，同时也标记了在启动并发标记周期时仍处于活动状态的所有未标记对象。该阶段还执行一些额外的清理操作，例如引用处理（参考疏散停顿日志）或类卸载。

1.645: [GC remark 1.645: [Finalize Marking, 0.0009461 secs] 1.646: [GC ref-proc, 
0.0000417 secs] 1.646: [Unloading, 0.0011301 secs], 0.0074056 secs]
[Times: user=0.01 sys=0.00, real=0.01 secs]

阶段 5：Cleanup

此最后阶段为即将到来的疏散阶段做准备，对堆区域中的所有活动对象进行计数，并根据预期的 GC 效率对这些区域进行排序。这里会执行维护工作，主要目的是维护并发标记的下一次迭代的内部状态。

最后，此阶段将 完全不包含活动对象的区域回收。这个阶段的一些部分是并发的，比如空区域的回收和大多数活动对象计算，但是它也需要一个短暂的 STW 暂停来完成这个动作。相关日志类似如下：

1.652: [GC cleanup 1213M->1213M(1885M), 0.0030492 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]

如果发现了一些仅包含垃圾的堆区域，则暂停格式可能会有所不同，类似于：

1.872: [GC cleanup 1357M->173M(1996M), 0.0015664 secs]
[Times: user=0.01 sys=0.00, real=0.01 secs]
1.874: [GC concurrent-cleanup-start]
1.876: [GC concurrent-cleanup-end, 0.0014846 secs]

Evacuation Pause: Mixed

并发清理可以释放 Old Generation 中的整个区域，事实上并发清理并非总是能够达到释放整个 Old Generation 的效果。成功完成并发标记后，G1 将触发一个混合收集的过程，混合收集不仅可以将垃圾从较年轻代区带走，还可以将大量的年老代扔到 collection set 中。

混合疏散停顿并不一定总是在并发标记阶段结束之后立即进行，这里有许多规则和推断会影响到这一点。例如，如果可以同时并发释放大部分 Old regions，则无需这样做。因此，在同时标记结束和混合疏散停顿之间可能很容易出现许多 fully-young 疏散停顿。

混合收集的过程与我们之前针对 fully-young gc 进行过的审查大致相同，但是这里还涵盖 *remembered sets* 的引入。

*remembered sets* 允许独立收集不同的堆区域。例如，当收集区域 A，B 和 C 时，我们必须知道是否有来自区域 D 和 E 的引用来确定它们的存活状态，但是遍历整个堆图将花费相当长的时间，并且破坏了增量收集的整个要点，因此采用了优化。就像我们用于在其他 GC 算法中独立收集 Young 区域的 Card Table 一样，在 G1 中则是通过 Remembered Sets 来完成。

如下图所示，每个区域都有一个 remembered sets ，该集合列出了从外部指向该区域的引用。这些引用将被视为其他 GC 根。在 Old regions 中，并发标记期间被确定为垃圾的对象将被忽略，即使有外部引用也是如此，在这种情况下，引用对象也是垃圾。

接下来就是多个并行 GC 线程找出哪些对象是活动的，哪些对象是垃圾：

最后，将活动对象移动到幸存者区，现在释放了空的区域。

为了维护 Remembered sets，在应用程序运行时，只要执行对字段的写入操作，就会发出 Post-Write Barrier。如果所得引用是跨 region 的，即从一个 region 指向另一个 region，则对应的条目将出现在目标 region 的 Remembered Set 中。为了减少写屏障带来的开销，将卡放入 Remembered Set 的过程是异步的，并且具有许多优化功能。但从根本上讲，归结为“写屏障”，即将脏卡信息放入本地缓冲区，然后由专门的 GC 线程将其拾取并将信息传播到引用 region 的 Remembered set。

混合模式下的日志大致如下：

[Update RS (ms)1`: Min: 0.7, Avg: 0.8, Max: 0.9, Diff: 0.2, Sum: 6.1]`

[ProcessedBuffers2`: Min: 0, Avg: 2.2, Max: 5, Diff: 5, Sum: 18]`

[Scan RS (ms)3`: Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.8]`

[Clear CT:0.2 ms]4

[RedirtyCards:0.1 ms]5

1.[Update RS (ms)–因为Rset是并发处理的，所以我们必须确保仍然处于缓冲状态的卡片在实际收集开始之前被处理。如果这个数字很高，那么并发 GC 线程将无法处理负载。例如，这可能是由于大量传入的字段修改，或者是由于 CPU 资源不足。
2.[ProcessedBuffers–每个工作线程处理了多少本地缓冲区。
3.[Scan RS (ms)–扫描来自Rset的引用需要多长时间。
4.[Clear CT:0.2 ms]–清理 card table 的耗时
5.[RedirtyCards:0.1 ms]–将 card table 中适当位置标记为脏位置所花费的时间。适当的位置是由 GC 自己对堆的变化来定义的，例如，在对引用进行排队时。

小结

G1 解决了 CMS 的一系列问题，从暂停可预测性到堆碎片。如果应用程序不受 CPU 利用率的限制，但对单个操作的延迟非常敏感。G1 的吞吐量开销更大，主要是它需要额外的写屏障和更多的活动后台线程。因此，如果应用程序处于吞吐量限制或消耗 100% 的CPU，并且不太关心单个暂停时间，那么 CMS 甚至并行 GC 可能是更好的选择。

总结

本篇主要是对JVM中的 GC 算法实现进行了介绍，并且通过一些主流的 GC 算法产生的日志进行了剖析，从 GC 日志进一步分解了 GC 的不同触发阶段和事件。希望通过本篇文章能够让读者能够更好的在实际工作中应用这些 GC 收集器，并且能够通过 GC 日志来理解 GC 的过程。

原文始发于微信公众号（PoemByte）：三谈 GC: GC 算法实现和日志