「这是我参与11月更文挑战的第10天，活动详情查看：2021最后一次更文挑战」

1.新生代垃圾回收

1）垃圾回收具体流程

能与CMS搭配使用的新生代垃圾收集器有Serial收集器和ParNew收集器。这2个收集器都采用标记复制算法，都会触发STW事件，停止所有的应用线程。不同之处在于，Serial是单线程执行，ParNew是多线程执行

2）ParNew日志分析

2021-10-16T10:47:36.645+0800: 164402.026: [GC (Allocation Failure) 164402.026: [ParNew: 1257248K->18599K(1393472K), 0.0276679 secs] 2578568K->1340913K(4039488K), 0.0280302 secs] [Times: user=0.09 sys=0.01, real=0.03 secs] 
2021-10-16T10:49:12.737+0800: 164498.119: [GC (Allocation Failure) 164498.119: [ParNew: 1257255K->18249K(1393472K), 0.0256398 secs] 2579569K->1342315K(4039488K), 0.0260383 secs] [Times: user=0.09 sys=0.00, real=0.03 secs] 

ParNew 收集器是年轻代常用的垃圾收集器，它采用的是复制算法，youngGC日志信息如下所示：

[GC (Allocation Failure) 164402.026: [ParNew: 1257248K->18599K(1393472K), 0.0276679 secs] 2578568K->1340913K(4039488K), 0.0280302 secs] [Times: user=0.09 sys=0.01, real=0.03 secs]

依次分析一下上面日志信息的含义：

2021-10-16T10:47:36.645+0800：Mirror GC 发生的时间；

164402.026：GC 开始时，相对 JVM 启动的相对时间，单位时秒，这里是45h+；

ParNew：收集器名称，这里是 ParNew 收集器，它使用的是并行的 mark-copy 算法，GC 过程也会 Stop the World；

1257248K->18599K：收集前后年轻代的使用情况，这里是 1.2G->18.16M；

1393472K：整个年轻代的容量，这里是 1.329G；

0.0276679 secs：Duration for the collection w/o final cleanup.

2578568K->1340913K：收集前后整个堆的使用情况，这里是 2.45G->1.28G;

4039488K：整个堆的容量，这里是 3.85G；

0.0280302 secs：ParNew 收集器标记和复制年轻代活着的对象所花费的时间（包括和老年代通信的开销、对象晋升到老年代开销、垃圾收集周期结束一些最后的清理对象等的花销）；

对于 [Times: user=0.09 sys=0.01, real=0.03 secs]，这里面涉及到三种时间类型，含义如下：

user：GC 线程在垃圾收集期间所使用的 CPU 总时间；

sys：系统调用或者等待系统事件花费的时间；

real：应用被暂停的时钟时间，由于 GC 线程是多线程的，导致了 real 小于 (user+real)，如果是 gc 线程是单线程的话，real 是接近于 (user+real) 时间。

2.老年代垃圾回收

1）垃圾回收具体流程

CMS GC以获取最小停顿时间为目的，尽可能减少STW时间，可以分为7个阶段

• 阶段 1: 初始标记(Initial Mark)

此阶段的目标是标记老年代中所有存活的对象, 包括 GC Root 的直接引用, 以及由新生代中存活对象所引用的对象，触发第一次STW事件

这个过程是支持多线程的（JDK7之前单线程，JDK8之后并行，可通过参数CMSParallelInitialMarkEnabled调整）

• 阶段 2: 并发标记(Concurrent Mark)

此阶段GC线程和应用线程并发执行，遍历阶段1初始标记出来的存活对象，然后继续递归标记这些对象可达的对象

• 阶段 3: 并发预清理(Concurrent Preclean)

此阶段GC线程和应用线程也是并发执行，因为阶段2是与应用线程并发执行，可能有些引用关系已经发生改变。 通过卡片标记(Card Marking)，提前把老年代空间逻辑划分为相等大小的区域(Card)，如果引用关系发生改变，JVM会将发生改变的区域标记位“脏区”(Dirty Card)，然后在本阶段，这些脏区会被找出来，刷新引用关系，清除“脏区”标记

• 阶段 4: 并发可取消的预清理(Concurrent Abortable Preclean)

此阶段也不停止应用线程. 本阶段尝试在 STW 的 最终标记阶段(Final Remark)之前尽可能地多做一些工作，以减少应用暂停时间 在该阶段不断循环处理：标记老年代的可达对象、扫描处理Dirty Card区域中的对象，循环的终止条件有： 1 达到循环次数 2 达到循环执行时间阈值 3 新生代内存使用率达到阈值

• 阶段 5: 最终标记(Final Remark)

这是GC事件中第二次(也是最后一次)STW阶段，目标是完成老年代中所有存活对象的标记。在此阶段执行： 1 遍历新生代对象，重新标记 2 根据GC Roots，重新标记 3 遍历老年代的Dirty Card，重新标记

• 阶段 6: 并发清除(Concurrent Sweep)

此阶段与应用程序并发执行，不需要STW停顿，根据标记结果清除垃圾对象

• 阶段 7: 并发重置(Concurrent Reset)

此阶段与应用程序并发执行，重置CMS算法相关的内部数据, 为下一次GC循环做准备

2）CMS日志分析

CMS GC 日志信息如下：

2021-10-16T10:49:12.784+0800: 164498.165: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1324065K(2646016K)] 1346967K(4039488K), 0.0408159 secs] [Times: user=0.01 sys=0.07, real=0.04 secs] 
2021-10-16T10:49:12.825+0800: 164498.206: [CMS-concurrent-mark-start]
2021-10-16T10:49:13.175+0800: 164498.557: [CMS-concurrent-mark: 0.350/0.350 secs] [Times: user=0.35 sys=0.04, real=0.35 secs] 
2021-10-16T10:49:13.176+0800: 164498.557: [CMS-concurrent-preclean-start]
2021-10-16T10:49:13.196+0800: 164498.577: [CMS-concurrent-preclean: 0.020/0.020 secs] [Times: user=0.02 sys=0.01, real=0.02 secs] 
2021-10-16T10:49:13.196+0800: 164498.577: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2021-10-16T10:49:18.245+0800: 164503.626: [CMS-concurrent-abortable-preclean: 4.941/5.049 secs] [Times: user=5.40 sys=0.00, real=5.05 secs] 
2021-10-16T10:49:18.246+0800: 164503.628: [GC (CMS Final Remark) [YG occupancy: 108466 K (1393472 K)]164503.628: [Rescan (parallel) , 0.0253410 secs]164503.653: [weak refs processing, 0.2311253 secs]164503.885: [class unloading, 0.0815292 secs]164503.966: [scrub symbol table, 0.0247088 secs]164503.991: [scrub string table, 0.0040060 secs][1 CMS-remark: 1324065K(2646016K)] 1432532K(4039488K), 0.4171240 secs] [Times: user=0.49 sys=0.00, real=0.42 secs] 
2021-10-16T10:49:18.664+0800: 164504.046: [CMS-concurrent-sweep-start]
2021-10-16T10:49:19.347+0800: 164504.728: [CMS-concurrent-sweep: 0.659/0.683 secs] [Times: user=0.94 sys=0.00, real=0.68 secs] 
2021-10-16T10:49:19.347+0800: 164504.728: [CMS-concurrent-reset-start]
2021-10-16T10:49:19.354+0800: 164504.735: [CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]  
2021-10-16T10:49:19.354+0800: 164504.735: [CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

CMS GC 拆分开来，涉及的阶段比较多，下面分别来介绍各个阶段的情况。

阶段1：Initial Mark

上述例子对应的日志信息为：

2021-10-16T10:49:12.784+0800: 164498.165: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1324065K(2646016K)] 1346967K(4039488K), 0.0408159 secs] [Times: user=0.01 sys=0.07, real=0.04 secs]

CMS-initial-mark：初始标记阶段，它会收集所有 GC Roots 以及其直接引用的对象；

1324065K：当前老年代使用的容量，这里是 1.26G；

(2646016K)：老年代可用的最大容量，这里是 2.52G；

1346967K：整个堆目前使用的容量，这里是 1.28G；

(24746432K)：堆可用的容量，这里是 23.6G；

0.0408159 secs：这个阶段的持续时间；

[Times: user=0.01 sys=0.07, real=0.04 secs]：与前面的类似，这里是相应 user、system and real 的时间统计。

阶段2：并发标记

这个阶段相应的日志信息如下：

2021-10-16T10:49:12.825+0800: 164498.206: [CMS-concurrent-mark-start]

2021-10-16T10:49:13.175+0800: 164498.557: [CMS-concurrent-mark: 0.350/0.350 secs] [Times: user=0.35 sys=0.04, real=0.35 secs]

这里详细对上面的日志解释，如下所示：

CMS-concurrent-mark：并发收集阶段，这个阶段会遍历老年代，并标记所有存活的对象；

0.350/0.350 secs：这个阶段的持续时间与时钟时间；

[Times: user=0.35 sys=0.04, real=0.35 secs] ：如前面所示，但是这部的时间，其实意义不大，因为它是从并发标记的开始时间开始计算，这期间因为是并发进行，不仅仅包含 GC 线程的工作。

阶段3：Concurrent Preclean

这个阶段相应的日志信息如下：

2021-10-16T10:49:13.176+0800: 164498.557: [CMS-concurrent-preclean-start]

2021-10-16T10:49:13.196+0800: 164498.577: [CMS-concurrent-preclean: 0.020/0.020 secs] [Times: user=0.02 sys=0.01, real=0.02 secs]

其含义为：

CMS-concurrent-preclean：Concurrent Preclean 阶段，对在前面并发标记阶段中引用发生变化的对象进行标记；

0.020/0.020 secs：这个阶段的持续时间与时钟时间；

[Times: user=0.02 sys=0.01, real=0.02 secs]：同并发标记阶段中的含义。

阶段4：Concurrent Abortable Preclean

这也是一个并发阶段，但是同样不会影响影响用户的应用线程，这个阶段是为了尽量承担 STW（stop-the-world）中最终标记阶段的工作。这个阶段持续时间依赖于很多的因素，由于这个阶段是在重复做很多相同的工作，直接满足一些条件（比如：重复迭代的次数、完成的工作量或者时钟时间等）。这个阶段的日志信息如下：

2021-10-16T10:49:13.196+0800: 164498.577: [CMS-concurrent-abortable-preclean-start]

2021-10-16T10:49:18.245+0800: 164503.626: [CMS-concurrent-abortable-preclean: 4.941/5.049 secs] [Times: user=5.40 sys=0.00, real=5.05 secs]

CMS-concurrent-abortable-preclean：Concurrent Abortable Preclean 阶段；

4.941/5.049 secs：这个阶段的持续时间与时钟时间，本质上，这里的 gc 线程会在 STW 之前做更多的工作，通常会持续 5s 左右；

[Times: user=5.40 sys=0.00, real=5.05 secs]：同前面。

阶段5：Final Remark

通常 CMS 的 Final Remark 阶段会在年轻代尽可能干净的时候运行，目的是为了减少连续 STW 发生的可能性（年轻代存活对象过多的话，也会导致老年代涉及的存活对象会很多）。这个阶段会比前面的几个阶段更复杂一些，相关日志如下：

2021-10-16T10:49:18.246+0800: 164503.628: [GC (CMS Final Remark) [YG occupancy: 108466 K (1393472 K)]164503.628: [Rescan (parallel) , 0.0253410 secs]164503.653: [weak refs processing, 0.2311253 secs]164503.885: [class unloading, 0.0815292 secs]164503.966: [scrub symbol table, 0.0247088 secs]164503.991: [scrub string table, 0.0040060 secs][1 CMS-remark: 1324065K(2646016K)] 1432532K(4039488K), 0.4171240 secs] [Times: user=0.49 sys=0.00, real=0.42 secs]

对上面的日志进行分析：

YG occupancy: 108466 K (1393472 K)：年轻代当前占用量及容量，这里分别是 105M 和 1.32G；

ParNew:...：触发了一次 young GC，这里触发的原因是为了减少年轻代的存活对象，尽量使年轻代更干净一些；

[Rescan (parallel) , 0.0253410 secs]：这个 Rescan 是当应用暂停的情况下完成对所有存活对象的标记，这个阶段是并行处理的，这里花费了 0.0253410s；

[weak refs processing, 0.2311253 secs]：第一个子阶段，它的工作是处理弱引用；

[class unloading, 0.0815292 secs]：第二个子阶段，它的工作是：unloading the unused classes；

[scrub symbol table, 0.0247088 secs] ... [scrub string table, 0.0040060 secs]：最后一个子阶段，它的目的是：cleaning up symbol and string tables which hold class-level metadata and internalized string respectively，时钟的暂停也包含在这里；

1324065K(2646016K)：这个阶段之后，老年代的使用量与总量，这里分别是 1.26G 和 2.52G；

1432532K(4039488K)：这个阶段之后，堆的使用量与总量（包括年轻代，年轻代在前面发生过 GC），这里分别是 1.36G 和 3.85G；

0.4171240 secs：这个阶段的持续时间；

[Times: user=0.49 sys=0.00, real=0.42 secs]：对应的时间信息。

3.GC日志图形分析工具

工具 gceasy，直接上传GC日志即可

主要关注几个点

JVM memory size 年轻代、老年代分配内存以及使用内存

CMS GC STW时间，以及各阶段时间

本文已参与「新人创作礼」活动，一起开启掘金创作之路。