JVM CMS Phases

Introduction

CMS：Concurrent Mark and Sweep，Mostly Concurrent Mark and Sweep Garbage Collector。

设计目标：年老代收集的时候避免长时间的暂停；

年轻代：采用 stop-the-world mark-copy 算法；
年老代：采用 Mostly Concurrent mark-sweep 算法；

能够达成该目标主要因为以下两个原因：

它不会花时间整理压缩年老代，而是维护了一个叫做 free-lists 的数据结构，该数据结构用来管理那些回收再利用的内存空间；
mark-sweep分为多个阶段，其中一大部分阶段GC的工作是和Application threads的工作同时进行的（当然，gc线程会和用户线程竞争CPU的时间），默认的GC的工作线程为你服务器物理CPU核数的1/4；

当你的服务器是多核同时你的目标是低延时，那该GC的搭配则是你的不二选择。

JVM测试参数如下标记：

Analyze

2016-08-23T02:23:07.219-0200: 64.322: [GC (Allocation Failure) 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]

2016-08-23T02:23:07.219-0200：GC发生的时间
64.322：GC开始，相对JVM启动的相对时间，单位是秒
GC：区别MinorGC和FullGC的标识，这次代表的是MinorGC
Allocation Failure：MinorGC的原因，在这个case里边，由于年轻代不满足申请的空间，因此触发了MinorGC
ParNew：收集器的名称，它预示了年轻代使用一个并行的 mark-copy stop-the-world 垃圾收集器
613404K->68068K：收集前后年轻代的使用情况
(613440K)：整个年轻代的容量
0.1020465 secs：Duration for the collection w/o final cleanup.
10885349K->10880154K：收集前后整个堆的使用情况
(12514816K)：整个堆的容量
0.1021309 secs：ParNew收集器标记和复制年轻代活着的对象所花费的时间（包括和老年代通信的开销、对象晋升到老年代时间、垃圾收集周期结束一些最后的清理对象等的开销）
[Times: user=0.78 sys=0.01, real=0.11 secs]：GC事件在不同维度的耗时
- user：Total CPU time that was consumed by Garbage Collector threads during this collection
- sys：Time spent in OS calls or waiting for system event
- real：Clock time for which your application was stopped. With Parallel GC this number should be close to (user time + system time) divided by the number of threads used by the Garbage Collector. In this particular case 8 threads were used. Note that due to some activities not being parallelizable, it always exceeds the ratio by a certain amount.

年轻代对象 -晋升-> 老年对象

开始的时候：整个堆的大小是10885349K，年轻代大小是613404K，这说明老年代大小是10885349-613404=10271945K

收集完成之后：整个堆的大小是10880154K，年轻代大小是68068K，这说明老年代大小是10880154-68068=10812086K

老年代的大小增加了：10812086-10271945=608209K，也就是说年轻代对象晋升到年老代对象的大小为608209K的数据

Full/Major GC

2016-08-23T11:23:07.321-0200: 64.425: [GC (CMS Initial Mark)1 [1 CMS-initial-mark: 10812086K(11901376K)] 10887844K(12514816K), 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2016-08-23T11:23:07.321-0200: 64.425: [CMS-concurrent-mark-start]
2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-mark2: 0.035/0.035 secs] [Times: user=0.07 sys=0.00, real=0.03 secs]
2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start]
2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-preclean3: 0.016/0.016 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start]
2016-08-23T11:23:08.446-0200: 65.550: [CMS-concurrent-abortable-preclean4: 0.167/1.074 secs] [Times: user=0.20 sys=0.00, real=1.07 secs]
2016-08-23T11:23:08.447-0200: 65.550: [GC (CMS Final Remark5)
[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]
2016-08-23T11:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start]
2016-08-23T11:23:08.485-0200: 65.588: [CMS-concurrent-sweep6: 0.027/0.027 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
2016-08-23T11:23:08.485-0200: 65.589: [CMS-concurrent-reset-start]
2016-08-23T11:23:08.497-0200: 65.601: [CMS-concurrent-reset7: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

Phase 1: Initial Mark

这是CMS中两次stop-the-world事件中的一次。它有两个目标：

标记老年代中所有的GC Roots；
标记被年轻代中活着的对象引用的对象。

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

CMS Initial Mark：收集阶段，开始收集所有的GC Roots和直接引用到的对象
10812086K：当前老年代使用情况
(11901376K)：老年代可用容量
10887844K：当前整个堆的使用情况
(12514816K)：整个堆的容量

Phase 2: Concurrent Mark

这个阶段会遍历整个老年代并且标记所有存活的对象，从“初始化标记”阶段找到的GC Roots开始。并发标记的特点是和应用程序线程同时运行。并不是老年代的所有存活对象都会被标记，因为标记的同时应用程序会改变一些对象的引用等。

在上边的图中，一个引用的箭头已经远离了当前对象（current obj）

1 2	2016-08-23T11:23:07.321-0200: 64.425: [CMS-concurrent-mark-start] 2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-mark2: 0.035/0.035 secs] [Times: user=0.07 sys=0.00, real=0.03 secs]

0.035/0.035 secs：展示该阶段持续的时间和时钟时间

Phase 3: Concurrent Preclean

这个阶段又是一个并发阶段，和应用线程并行运行，不会中断应用线程。

前一个阶段在并行运行的时候，一些对象的引用已经发生了变化，当这些引用发生变化的时候，JVM会标记堆的这个区域为Dirty Card(包含被标记但是改变了的对象，被认为”dirty”)，这就是Card Marking。

在pre-clean阶段，那些能够从dirty card对象到达的对象也会被标记，这个标记做完之后，dirty card标记就会被清除了，如下：

另外，一些必要的清扫工作也会做，还会做一些final remark阶段需要的准备工作；

Phase 4: Concurrent Abortable Preclean

又一个并发阶段不会停止应用程序线程。这个阶段尝试着去承担STW的Final Remark阶段足够多的工作。这个阶段持续的时间依赖好多的因素，由于这个阶段是重复的做相同的事情直到发生aboart的条件（比如：重复的次数、多少量的工作、持续的时间等等）之一才会停止。

1
2

2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start]
2016-08-23T11:23:08.446-0200: 65.550: [CMS-concurrent-abortable-preclean4: 0.167/1.074 secs] [Times: user=0.20 sys=0.00, real=1.07 secs]

这个阶段很大程度的影响着即将来临的Final Remark的停顿，有相当一部分重要的configuration options和失败的模式；

Phase 5: Final Remark

这个阶段是CMS中第二个并且是最后一个STW的阶段。该阶段的任务是完成标记整个年老代的所有的存活对象。由于之前的预处理是并发的，它可能跟不上应用程序改变的速度，这个时候，STW是非常需要的来完成这个严酷考验的阶段。

通常CMS尽量运行Final Remark阶段在年轻代是足够干净的时候，目的是消除紧接着的连续的几个STW阶段。

2016-08-23T11:23:08.447-0200: 65.550: [GC (CMS Final Remark5)
[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]

weak refs processing, 0.0000243 secs：第一个子阶段，随着这个阶段的进行处理弱引用
class unloading, 0.0013120 secs]65.560：第二个子阶段(that is unloading the unused classes, with the duration and timestamp of the phase)
scrub string table, 0.0001759 secs：最后一个子阶段（that is cleaning up symbol and string tables which hold class-level metadata and internalized string respectively）
10812086K(11901376K)：在这个阶段之后老年代占有的内存大小和老年代的容量
11200006K(12514816K)：在这个阶段之后整个堆的内存大小和整个堆的容量
0.0110730 secs：这个阶段的持续时间

通过以上5个阶段的标记，老年代所有存活的对象已经被标记并且现在要通过Garbage Collector采用清扫的方式回收那些不能用的对象了。

Phase 6: Concurrent Sweep

和应用线程同时进行，不需要STW。这个阶段的目的就是移除那些不用的对象，回收他们占用的空间并且为将来使用。

Phase 7: Concurrent Reset

这个阶段并发执行，重新设置CMS算法内部的数据结构，准备下一个CMS生命周期的使用。

Other GC log

{Heap before GC invocations=537 (full 5):
 def new generation   total 76032K, used 68480K [0x00000000e2200000, 0x00000000e7470000, 0x00000000ec150000)
  eden space 67648K, 100% used [0x00000000e2200000, 0x00000000e6410000, 0x00000000e6410000)
  from space 8384K,   9% used [0x00000000e6c40000, 0x00000000e6d101c8, 0x00000000e7470000)
  to   space 8384K,   0% used [0x00000000e6410000, 0x00000000e6410000, 0x00000000e6c40000)
 tenured generation   total 168760K, used 120244K [0x00000000ec150000, 0x00000000f661e000, 0x0000000100000000)
   the space 168760K,  71% used [0x00000000ec150000, 0x00000000f36bd1e0, 0x00000000f36bd200, 0x00000000f661e000)
 Metaspace       used 57113K, capacity 59188K, committed 59520K, reserved 1101824K
  class space    used 7298K, capacity 7692K, committed 7808K, reserved 1048576K
856.767: [GC (Allocation Failure) 856.767: [DefNew: 68480K->935K(76032K), 0.0079443 secs] 188724K->121180K(244792K), 0.0080136 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

Heap after GC invocations=538 (full 5):
 def new generation   total 76032K, used 935K [0x00000000e2200000, 0x00000000e7470000, 0x00000000ec150000)
  eden space 67648K,   0% used [0x00000000e2200000, 0x00000000e2200000, 0x00000000e6410000)
  from space 8384K,  11% used [0x00000000e6410000, 0x00000000e64f9df8, 0x00000000e6c40000)
  to   space 8384K,   0% used [0x00000000e6c40000, 0x00000000e6c40000, 0x00000000e7470000)
 tenured generation   total 168760K, used 120245K [0x00000000ec150000, 0x00000000f661e000, 0x0000000100000000)
   the space 168760K,  71% used [0x00000000ec150000, 0x00000000f36bd5f0, 0x00000000f36bd600, 0x00000000f661e000)
 Metaspace       used 57113K, capacity 59188K, committed 59520K, reserved 1101824K
  class space    used 7298K, capacity 7692K, committed 7808K, reserved 1048576K
}

Reference

https://www.cnblogs.com/zhangxiaoguang/p/5792468.html
https://plumbr.io/handbook/what-is-garbage-collection