CMS GC日志详细分析

一 日志分析
以下分析都基于hotspot 1.6.0_26配置如下参数产生的：


配置参数如下：
Xms=Xmx=7804M=7991296K 
PermSize=MaxPermSize=256M
Xmn=2926M=2996224K
Old=7804-2926=4995072K
CMSInitiatingOccupancyFraction=75
eden=2926*8/10=2340.8M
s0=s1=2926/10=292.6M
Eden+s0=2633.4M=2696640K

日志分析开始：
2013-11-23T09:50:54.011+0800: [GC [1 CMS-initial-mark: 3746947K(4995072K)] 3767067K(7691712K), 0.0340870 secs] [Times: user=0.04 sys=0.00, real=0.03 secs] 
初始标记：会暂停应用，单线程（由user和real=0.03几乎相等可以看出）。
只标记根能直接可达的对象，故很快。
3746947K(4995072K)表示老年代占用3746947K，4995072K表示老年代容量，3746947/4995072=0.7501
由于达到的阈值75%，开始进行Full GC。


2013-11-23T09:50:54.729+0800: [CMS-concurrent-mark: 0.683/0.683 secs] [Times: user=3.32 sys=0.18, real=0.69 secs]
并发标记：不会暂停应用


2013-11-23T09:50:54.762+0800: [CMS-concurrent-preclean: 0.031/0.032 secs] [Times: user=0.07 sys=0.00, real=0.03 secs] 
预清理：不会暂停应用
该阶段检查并发标记阶段时从新生代晋升的对象，或新分配的对象，或被应用程序线程更新过的对象，帮助减少重新标记阶段的暂停时间。
如果在此之后，Eden的占用量>CMSScheduleRemarkEdenSizeThreshold(默认为2M),会启动CMS-concurrent-abortable-preclean

预清理阶段只是一个取样过程，它将新生代按一定间隔进行分块，标记起始位置，以便remark时可以并行的的对块进行trace。不必从开头一点一点进行trace，预清理阶段时，最好发生一次ygc.
https://blogs.oracle.com/jonthecollector/entry/did_you_know

CMS: abort preclean due to time 2013-11-23T09:50:59.894+0800: [CMS-concurrent-abortable-preclean: 5.076/5.132 secs] [Times: user=12.94 sys=1.00, real=5.13 secs] 
可终止的预清理：不会暂停应用
继续预清理，至到Eden区占用量达到CMSScheduleRemarkEdenPenetration(默认50%)，或达到5秒钟。
但是如果ygc在这个阶段中没有发生的话，是达不到理想效果的。
此时可以指定CMSMaxAbortablePrecleanTime，但是，等待一般都不是什么好的策略，可以采用CMSScavengeBeforeRemark，使remark之前发生一次ygc，从而减少remark阶段暂停的时间。

2013-11-23T09:50:59.902+0800: [GC[YG occupancy: 2103894 K (2696640 K)][Rescan (parallel) , 1.5680650 secs][weak refs processing, 0.8144200 secs] [1 CMS-remark: 3746947K(4995072K)] 5850842K(7691712K), 2.4045340 secs] [Times: user=17.41 sys=0.00, real=2.40 secs] 
2013-11-23T09:51:02.952+0800: [GC [ParNew: 2416818K->24727K(2696640K), 0.0307790 secs] 6077674K->3685848K(7691712K), 0.0327600 secs] [Times: user=0.24 sys=0.00, real=0.03 secs] 
重新标记：会暂停应用，多线程，通过ParallelGCThreads指定，此阶段是CMS中暂停时间最长的。
重新从根扫描新生代中剩余的更新过的对象，也会处理其引用对象。


2013-11-23T09:51:07.162+0800: [CMS-concurrent-sweep: 4.452/4.853 secs] [Times: user=16.20 sys=1.31, real=4.86 secs]
并发清理：不会暂停应用


2013-11-23T09:51:07.175+0800: [CMS-concurrent-reset: 0.013/0.013 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
重置：cms数据结构重新初始化，为下一次cms准备。


二 CMS GC原因总结:
1 System.gc() -> 可以通过DisableExplicitGC禁止
2 旧生代剩余空间达到阈值 -> CMSInitiatingOccupancyFraction
3 永久代剩余空间达到阈值 -> 通过CMSClassUnloadingEnabled启用cms回收永久代，否则永久代回收采用Serial old收集。阈值通过CMSInitiatingPermOccupancyFraction指定。
4 promotion failed -> YGC时，S区域放不下，而此时旧生带也放不下
  此时不一定是老年代剩余空间不足，也可能是晋升的对象需要连续的空间，而老年代连续的空间不足导致的。CMS会产生碎片，但1.6.0_26UseCMSCompactAtFullCollection默认是开启的，即cms回收完进行一次整理
5 concurrent mode failure -> CMS GC的时候同时YGC进行着，导致CMS完成前老年代空间被占满（full promotion guarantee failure），改错误会导致Full GC，导致GC时间变长，可以调小CMSInitiatingOccupancyFraction或调小新生代
6 统计得到的minor GC晋升到旧生代的平均大小大于旧生代的剩余空间 -> HandlePromotionFailure，但是经试验1.6.0_26没有此参数


三 难理解的参数说明：
1 CMSFullGCsBeforeCompaction
CMS并发GC不是“full GC”。HotSpot VM里对concurrent collection和full collection有明确的区分。所有带有“FullCollection”字样的VM参数都是跟真正的full GC相关，而跟CMS并发GC无关的。 
CMS GC要决定是否在full GC时做压缩，会依赖几个条件。其中， 
第一种条件，UseCMSCompactAtFullCollection 与 CMSFullGCsBeforeCompaction 是搭配使用的；前者目前默认就是true了，也就是关键在后者上。 
第二种条件是用户调用了System.gc()，而且DisableExplicitGC没有开启。 
第三种条件是young gen报告接下来如果做增量收集会失败；简单来说也就是young gen预计old gen没有足够空间来容纳下次young GC晋升的对象。 

上述三种条件的任意一种成立都会让CMS决定这次做full GC时要做压缩。 
（还有另一个参数，CMSCompactWhenClearAllSoftRefs，默认也是true） 

CMSFullGCsBeforeCompaction 说的是，在上一次CMS并发GC执行过后，到底还要再执行多少次full GC才会做压缩。默认是0，也就是在默认配置下每次CMS GC顶不住了而要转入full GC的时候都会做压缩。 
把CMSFullGCsBeforeCompaction配置为10，就会让上面说的第一个条件变成每隔10次真正的full GC才做一次压缩（而不是每10次CMS并发GC就做一次压缩，目前VM里没有这样的参数）。这会使full GC更少做压缩，也就更容易使CMS的old gen受碎片化问题的困扰。 
本来这个参数就是用来配置降低full GC压缩的频率，以期减少某些full GC的暂停时间。CMS回退到full GC时用的算法是mark-sweep-compact，但compaction是可选的，不做的话碎片化会严重些但这次full GC的暂停时间会短些；这是个取舍。