[JVM] 看GC日志学垃圾回收 - CMS

首先是一段GC日志

2020-01-13T16:23:07.321-0200: 64.425: [GC (CMS Initial Mark) [1 CMS-initial-mark:
10812086K(11901376K)] 10887844K(12514816K), 0.0001997 secs] [Times: user=0.00 sys=0.00,
real=0.00 secs]
2020-01-13T16:23:07.321-0200: 64.425: [CMS-concurrent-mark-start]
2020-01-13T16: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]
2020-01-13T16:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start]
2020-01-13T16: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]
2020-01-13T16:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start]
2020-01-13T16: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]
2020-01-13T16:23:08.447-0200: 65.550: [GC (CMS Final Remark) [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]
2020-01-13T16:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start]
2020-01-13T16: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]
2020-01-13T16:23:08.485-0200: 65.589: [CMS-concurrent-reset-start]
2020-01-13T16: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]

从日志中可以看出，CMS分为以下几个阶段：

CMS Initial Mark：初始标记
CMS concurrent mark：并发标记
CMS concurrent preclean：并发预清理
CMS concurrent abortable preclean：并发可中断的预清理
CMS Final Remark：最终标记
CMS concurrent sweep：并发清除
CMS concurrent reset：并发重置

CMS Initial Mark

初始标记阶段，需要stop-the-world，该阶段的目标：找出所有的GC Roots，它们通常是一下几类对象：

Local variables
Static variables
Active threads
JNI References

2020-01-13T16:23:07.321-0200: 64.425: [GC (CMS Initial Mark) [1 CMS-initial-mark:
10812086K(11901376K)] 10887844K(12514816K), 0.0001997 secs] [Times: user=0.00 sys=0.00,
real=0.00 secs]

2020-01-13T16:23:07.321-0200: 64.425：GC开始的时间
CMS Initial Mark：CMS GC的第一个阶段，Initial Mark
10812086K(11901376K)：老年代当前使用量(老年代空间总可用空间)
10887844K(12514816K)：堆空间当前使用量(堆空间总可用空间)
0.0001997 secs：CMS Initial Mark消耗的时间
Times: user=0.00 sys=0.00,real=0.00 secs：该阶段的总耗时
- user：该阶段消耗的CPU时间
- sys：该阶段中系统进行调用或者等待的耗时
- real：user / 并发线程数，即该阶段所消耗的总的时间

CMS concurrent mark

并发标记阶段，不需要stop-the-world，也就是可以和用户线程并行，需要给GC线程分配1/4 cpu cores线程数来执行GC，这个阶段主要的目标：从Initial Mark阶段找出的GC Roots开始，遍历对象图，然后标记出所有的存活对象

2020-01-13T16:23:07.321-0200: 64.425: [CMS-concurrent-mark-start]
2020-01-13T16: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]

CMS concurrent preclean

并发预清理阶段，不需要stop-the-world，由于concurrent mark阶段是和用户线程并发进行的，因此在过程中引用关系很可能会发生改变，有的对象可能已经被JVM标记为dirty，同时有可能会出现存活的对象没有被标记的情况，为了避免这些情况发生所以有了preclean 阶段，该阶段的主要目标：处理那些在concurrent mark阶段由于用户线程导致引用关系改变的对象

2020-01-13T16:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start]
2020-01-13T16: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]

CMS concurrent abortable preclean

并发可中断的预清理阶段，不需要stop-the-world，跟preclean阶段做的工作差不多，不同的是，这个阶段是可以被中断的，该阶段的目标：减少Final Remark阶段的工作量

2020-01-13T16:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start]
2020-01-13T16: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]

CMS Final Remark

最终标记阶段，需要stop-the-world，这是CMS中的最后一个需要stop-the-world的阶段，该阶段的目标：标记所有的老年代的存活对象，包括那些在并发标记3个阶段期间发生引用关系变化的存活对象，该阶段通常会在新生代被清空的情况下执行，目的是为了消除多次进行stop-the-world带来的影响

2020-01-13T16:23:08.447-0200: 65.550: [GC (CMS Final Remark) [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]

2020-01-13T16:23:08.447-0200: 65.550：GC开始的时间
CMS Final Remark：CMS 最终标记阶段
YG occupancy: 387920 K(613440 K)]：新生代已使用量(总量)
Rescan (parallel), 0.0085125 secs：标记所有的存活对象，耗时0.0085125secs
weak refs processing, 0.0000243 secs：第一个子阶段，处理弱引用
class unloading, 0.0013120 secs：第二个子阶段，卸载无用的class
scrub symbol table, 0.0008345 secs：最后一个子阶段，清理持有class-level metadata的string tables和一些symbol
10812086K(11901376K)：该阶段结束时老年代已使用量(总量)
11200006K(12514816K)：该阶段结束时堆空间已使用量(总量)
0.0110730 secs：该阶段耗时
Times: user=0.06 sys=0.00, real=0.01 secs：整个阶段耗时

CMS concurrent sweep

并发清除阶段，不需要stop-the-world，该阶段的目标：清理掉垃圾对象

2020-01-13T16:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start]
2020-01-13T16: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]

CMS concurrent reset

并发重置阶段，不需要stop-the-world，该阶段的目标是：重置CMS内部数据结构，为下一次回收做准备

2020-01-13T16:23:08.485-0200: 65.589: [CMS-concurrent-reset-start]
2020-01-13T16: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]

Daniel's Blog