使用CMS垃圾收集器时，加上-XX:+PrintGCDetails和-XX:+PrintGCTimeStamps参数将会是我们得到更过的日志信息。了解这些信息有助于CMS垃圾收集器的各种参数调整，以实现最佳的性能。
我们先来大致看一下1.4.2_10版本的CMS收集器的日志信息。
39.910: [GC 39.910: [ParNew: 261760K->0K(261952K), 0.2314667 secs] 262017K->26386K(1048384K), 0.2318679 secs]
年轻代大小为261952，经过一次垃圾收集，年轻代的内存占用由261760K变为0。这次垃圾收集花费0.2318679秒。
40.146: [GC [1 CMS-initial-mark: 26386K(786432K)] 26404K(1048384K), 0.0074495 secs]
这是CMS收集器对老年代开始收集的标志。初始标记阶段遍历从根对象出发可达的对象。这个阶段会暂停应用线程的执行(STW)。老年代的空间大小为786432K，标记的对象占用空间为26386K。
40.154: [CMS-concurrent-mark-start]
CMS开始并发标记阶段，在初始标记阶段暂停的应用程序线程可以继续执行。这个阶段标记从初始标记阶段标记的对象出发仍然可达的对象。
40.683: [CMS-concurrent-mark: 0.521/0.529 secs]
并发标记占用0.521秒的CPU时间，还有0.529秒的wall time that includes the yield to other threads alse
40.683: [CMS-concurrent-preclean-start]
*预清理阶段
预清理阶段同样是并发的过程。we look at the objects in CMS heap which got updated by promotions from young generation or new allocations or got updated by mutators while we were doing the concurrent marking in the previous concurrent marking phase. 通过同时重新扫描这些对象，预清理阶段有助于减少在下一个处理过程的工作。而下一个处理动作是需要STW的重新标记阶段。
40.701: [CMS-concurrent-preclean: 0.017/0.018 secs]
进行预清理的CPU总时间为0.017秒，wall time为0.018秒
40.704: [GC40.704: [Rescan (parallel) , 0.1790103 secs]
40.883: [weak refs processing, 0.0100966 secs] [1 CMS-remark: 26386K(786432K)] 52644K(1048384K), 0.1897792 secs]
这个阶段会STW，此阶段重新扫描堆中的所有残留的更新过的对象，从根部回溯并处理引用对象。重新扫描的工作时间为0.1790103秒，弱引用对象处理时间为0.0100966秒。这一阶段共完成0.1897792秒。
40.894: [CMS-concurrent-sweep-start]
开始清理死亡/未标记的对象。清理是与所有其他线程一起运行的并发阶段。
41.020: [CMS-concurrent-sweep: 0.126/0.126 secs]
清理垃圾花了0.126秒
41.020: [CMS-concurrent-reset-start]
开始重置。
41.147: [CMS-concurrent-reset: 0.127/0.127 secs]
在这个阶段，CMS数据结构将被重新初始化，以便稍后可以开始一个新的循环。在这种情况下，花了0.127秒。
这是一个正常的CMS周期运行。现在让我们看看其他一些CMS日志条目：
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的，但是ParNew并没有执行垃圾收集工作。因为根据估计，CMS的管理空间无法容纳最坏情况下年轻代里存活的对象。我们把这个失败命名为“full promotion guarantee failure”。
由于这个原因，CMS的并发模式被中断，一个Full GC在197.981启动。This mark-sweep-compact stop-the-world Full GC took 2.3733725 secs and the CMS generation space occupancy dropped from 402978K to 248977K.
可以通过设置更大的老年代空间或者降低触发CMS收集器启动所需要的内存来避免concurrent mode failer。将CMSInitiatingOccupancyFraction设置成更小的值并且将UseCmsInitialtingOccupancyOnly设置成true来减低触发GC需要的内存。应该适当选择CMSInitiatingOccupancyFraction的值，因为将其设置为非常低的值将导致过于频繁的CMS收集。
有时候即使日志显示老年代中有足够的可用空间，仍然会发生升级失败的现象。原因就是内存的碎片化，在老年代的内存不连续，而年轻代到老年代的晋升需要足够大的连续空间。CMS收集器是一个非压缩收集器，因此可能会导致某些类型的应用程序的空间碎片化。
从1.5开始，对于CMS收集器，对象晋升时内存的检查将采用不同以前的方式。不再将所有的年轻代对象全部晋升视为最坏的情况。而是根据最近的GC进行评估。评估的值通常比最坏情况下的晋升对象要小得多，因此老年代需要的空间更少。如果对象晋升的过程失败，那么年轻代会处于稳定的状态，并且STW的标记-清理收集器会开始启动。在失败后的处理过程中，要使用UseSerialGC获得相同的功能，您需要明确指定开关-XX:+HandlePromotionFailure。
283.736: [Full GC 283.736: [ParNew: 261599K->261599K(261952K), 0.0000615 secs] 826554K->826554K(1048384K), 0.0003259 secs]
GC locker: Trying a full collection because scavenge failed
283.736: [Full GC 283.736: [ParNew: 261599K->261599K(261952K), 0.0000288 secs].
JNI关键部分发布时STW。这里，年轻一代收集由于“full promotion guarantee failure”而再次失败，然后Full GC正在被调用。
网友评论