基于日志理解 cms 原理,为什么remark要stop the world?(理解CMS GC日志.)

翻译转 理解CMS GC日志

本文翻译自：
https://blogs.oracle.com/poonam/entry/understanding_cms_gc_logs

加入自己的思考,特别是为什么remark要stop the world?(同理[b] init-remark)[/b]

我本来想:既然有Foating Garbage存在,为什么还要费那么大资源(stop the world)把变化了的 unreachable 给找出来. 直接放到下次回收就好了.

  

CMSInitiatingOccupancyFraction值与Xmn的关系公式: http://www.cnblogs.com/redcreen/archive/2011/05/04/2037057.html#CMSInitiatingOccupancyFraction_value
 :
   其他调优实战:https://elasticsearch.cn/article/118

  源码对照 cms: http://www.68idc.cn/help/makewebs/JSP/20160619619932.html
  著名的jon博客:https://blogs.oracle.com/jonthecollector/did-you-know

准备工作

JVM的GC日志的主要参数包括如下几个：

-XX:+PrintGC 输出GC日志

-XX:+PrintGCDetails 输出GC的详细日志

-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）

-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如2013-05-04T21:53:59.234+0800）

-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息

-Xloggc:../logs/gc.log 日志文件的输出路径

CMS GC知识

CMS，全称Concurrent Mark and Sweep,用于对年老代进行回收，目标是尽量减少应用的暂停时间，减少full gc发生的机率，利用和应用程序线程并发的垃圾回收线程来标记清除年老代。

CMS并非没有暂停，而是用两次短暂停来替代串行标记整理算法的长暂停，内外的设置正常收集周期是这样的：

　　1、CMS-initial-mark 初始标记

　　2、CMS-concurrent-mark 并发标记的

　　3、CMS-concurrent-preclean 执行预清理.  phil 注: 相当于两次 concurrent-mark. 因为上一次c mark,太长.会有很多 changed object 出现.先干掉这波.到最好的 stop the world 的 remark 阶段,changed object 会少很多.

　　4、CMS-concurrent-abortable-preclean 执行可中止预清理 //

　　5、CMS-remark 重新标记

　　6、CMS-concurrent-sweep 并发清除

　　7、CMS-concurrent-reset 并发重设状态等待下次CMS的触发

其中，CMS-initial-mark和CMS-remark会stop-the-world。

具体CMS的原理可以参看这篇文章
了解CMS(Concurrent Mark-Sweep)垃圾回收器

phil 注:

   cms 新生代使用的paral ser 回收. stop the world. ocation

   cms 老生带分为 allocated 和 free.其中cms 垃圾回收器会将 allocated 分为 reachable 和 unreachable.

   关键点: allocated时时在变

   所以为什么remark要stop the world?:

   1. 用户线程和 c mark 线程存在并发竞争.

     1.1A 独立, B 引用 C.  cmark先遍历了 A, cmark 线程遍历到 B 时, 用户线程将 C 给了 A.  这时候 C 没有被 reachable 到. 最后认为 C 是 unreable 的.其实并不是

    1.2. 另外已分配的池也时时变大. 如果不锁住,也会被有问题.导致 unreachable 计算的有误.

   参考http://stackoverflow.com/questions/29846041/why-remark-phase-is-needed-on-concurrent-gc

理解CMS GC日志

启动jvm的时候，增加参数-XX:+PrintGCDetails 和 -XX:+PrintGCTimeStamps可以打印出CMS GC的详细日志。读懂log信息有助于应用系统的各种参数调优，同时也有助于使得CMS实现更好的性能。

下面的例子使用了1.8的jvm

2016-12-21T15:05:30.175+0800: 90.439: [GC2016-12-21T15:05:30.175+0800: 90.439: [ParNew: 720896K->49062K(720896K), 0.2289360 secs] 864443K->262770K(1507328K), 0.2292340 secs] [Times: user=0.42 sys=0.00, real=0.23 secs]

Young generation(ParNew)收集。新生代的容量是720896K，在使用量达到了720896K时发生了GC，回收的Young generation容量为49062K。本次GC花费了0.2289360s

2016-12-21T15:05:14.628+0800: 74.892: [GC [1 CMS-initial-mark: 646746K(786432K)] 723228K(1507328K), 0.0456000 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]

CMS开始回收tenured generation collection。这阶段是CMS初始化标记的阶段，从垃圾回收的“根对象”开始，且只扫描直接与“根对象”直接关联的对象，并做标记，在此期间，其他线程都会停止。

tenured generation的空间是786432K，在容量为646746K时开始执行初始标记。


2016-12-21T15:05:14.674+0800: 74.938: [CMS-concurrent-mark-start]


Concurrent marking(并发标记)阶段开始。

本阶段，其他线程重新开始正常执行，在上一步初始对象的基础上继续向下追溯标记


2016-12-21T15:05:15.188+0800: 75.452: [CMS-concurrent-mark: 0.513/0.514 secs] [Times: user=0.95 sys=0.05, real=0.52 secs]


并发标记阶段发费了0.513s cpu time 和0.514s 系统时间（包括其他线程占用cpu导致标记线程挂起的时间）


2016-12-21T15:05:15.188+0800: 75.452: [CMS-concurrent-preclean-start]


concurrent-preclean(并发域清理)阶段开始

并发预清理阶段仍然是并发的。在这个阶段，虚拟机查找在执行并发标记阶段新进入老年代的对象(可能会有一些对象从新生代晋升到老年代， 或者有一些对象被分配到老年代)。通过重新扫描，减少下一个阶段"重新标记"的工作，因为下一个阶段会Stop The World。

phil 注:


2016-12-21T15:05:15.192+0800: 75.456: [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]


concurrent-preclean花费了0.004s cpu time 和 0.004s 系统时间


2016-12-21T15:05:20.256+0800: 80.521: [GC[YG occupancy: 377234 K (720896 K)]2016-12-21T15:05:20.256+0800: 80.521: [Rescan (parallel) , 0.3789280 secs]2016-12-21T15:05:20.635+0800:
80.900: [weak refs processing, 0.0017780 secs]2016-12-21T15:05:20.637+0800: 80.901: [class unloading, 0.0141220 secs]2016-12-21T15:05:20.651+0800: 80.916: [scrub symbol table, 0.0259990 secs]2016-12-21T15:05:20.677+0800: 80.942: [scrub string table, 0.0024140
secs] [1 CMS-remark: 646746K(786432K)] 1023980K(1507328K), 0.4268320 secs] [Times: user=0.78 sys=0.01, real=0.42 secs]

rescan阶段，会暂停其他线程。重新扫描CMS堆中剩余的对象，重新从“根对象”开始扫描，并且也会处理对象关联。本次扫描花费了 0.3789280s，其中弱引用对象（weak referene objects）处理大约用来0.0017780s，本阶段共计时间0.4268320s

phil 注: 原文描述错误. rescan阶段的描述错了. 如果又是从根开始,那么和并发标记就没啥区别了,会很耗时.

其实 cms 中有个 card table 的.

另外官网https://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/cms.html

也明确说明只查变化了的.

Stop all application threads and retrace sections of the roots and object graph that may have been modified since they were last examined, and then resume all application threads.

其中 新生代(隔代引用也是根)



2016-12-21T15:05:20.685+0800: 80.950: [CMS-concurrent-sweep-start]


开始清理没有标记的对象，清理阶段是和其他线程并发进行的。



2016-12-21T15:05:21.340+0800: 81.605: [CMS-concurrent-sweep: 0.640/0.655 secs] [Times: user=1.23 sys=0.03, real=0.66 secs]


时间，不解释了



2016-12-21T15:05:21.341+0800: 81.605: [CMS-concurrent-reset-start]

2016-12-21T15:05:21.402+0800: 81.666: [CMS-concurrent-reset: 0.061/0.061 secs] [Times: user=0.06 sys=0.05, real=0.06 secs]


reset 阶段开始，并且输出所用时间。在这个阶段，与CMS相关数据结构被重新初始化，这样下一个周期可以正常进行。

以上过程是一个正常的CMS GC循环周期,接下来再分析一些不正常的日志

以下这个情况我没有复现，用的是文章的中数据，TODO之后想想能否打印出来这种情况



197.976: [GC 197.976: [ParNew: 260872K->260872K(261952K), 0.0000688 secs]197.976: [CMS197.981: [CMS-concurrent-sweep: 0.516/0.531 secs]

(concurrent mode failure): 402978K->248977K(786432K), 2.3728734 secs] 663850K->248977K(1048384K), 2.3733725 secs]


这显示，ParNew收集请求执行，但是没有成功。因为此时系统估计没有老生代中没有足够的空间去容纳这些对象（预测之后可能会出现老生代的空余空间将会被系统占光），我们称这种情况为 “full promotion guarantee failure”

在这种情况下下，并发式的CMS被阻塞了，full GC执行了，GC算法进入了concurrent mode failure状态，调用一个serail Old GC(阻塞了其他线程)来清理系统的Heap

日志显示，Full GC花费了2.3733725s，老生代空间由402978K降到了248977K

concurrent mode failure可以通过增大老生代的空间或者通过设置CMSInitiatingOccupancyFraction一个小的值使得CMS Collection发生的更频繁（CMSInitiatingOccupancyFraction可以控制CMS执行的时间，假设设置为70，说明老生代在利用率为70%时发生CMS），但是把这个值设置小也会导致CMS发生更加频繁。

某些情况下，promotion failures也会发生，即使是老生代有足够的空间。这个原因是"fragmentation"-老生代的可用空间不是连续的，而将新生代的对象移动到老生代需要连续的可用空间。而CMS是不会对内存进行压缩的算法，因此造成了这种问题。TODO，这篇文章解决了这个问题，我还没读

补充一下：concurrent mode failure产生的原理：CMS并发处理阶段用户线程还在运行中，伴随着程序运行会有新的垃圾产生，CMS无法处理掉它们（没有标记），只能在下一次GC的时候处理。同样的，用户线程运行就需要分配新的内存空间，为此，CMS收集器并不会在老年代全部被填满以后在进行收集，会预留一部分空间提供并发收集时的程序运行使用。即使是这样，还是会存在CMS运行期间预留的内存无法满足程序需求，就会出现"Concurrent Mode Failure"失败，这是，虚拟机将会启动备案操作：临时启动Serial
Old 收集器来重新进行老年代的垃圾收集，Serial Old收集器会Stop the world，这样会导致停顿时间过长

同样的，CMS收集结束后会有大量的碎片空间差生，也会给大对象分配带来麻烦，往往会出现老年代还有很大空间剩余，但是无法找到足够多的连续空间来分配当前对象，不得不提前触发一次Full GC



197.976: [GC 197.976: [ParNew: 260872K->260872K(261952K), 0.0000688 secs]197.976: [CMS197.981: [CMS-concurrent-sweep: 0.516/0.531 secs] (concurrent mode failure): 402978K->248977K(786432K), 2.3728734 secs] 663850K->248977K(1048384K), 2.3733725 secs]


这行GC日志显示的是一个请求失败的新生代GC处理。因为没有足够的空间来存储由新生代晋升上来的对象。这种现象称之为full promotioin guarantee failure 就此会在197.981处产生一次FULL GC，花费了 2.3733725秒 ，从而使CMS的空间从 402978K->248977K.