最近遇到一个频繁CMS的case，日志如下：
老年代的占用非常少，初步判断：并非由达到设置的内存比例触发，有可能是System.gc()或者permGen引发的CMS
【排查过程1】
增加日志，可以清楚看见，3个区的使用量都非常少
而gccause无法定位触发原因，只打印了CMS两个暂停阶段的信息
于是重新整理了一下background式CMS的触发点：
1、System.gc() + ExplicitGCInvokesConcurrent引起的
----确实设置了ExplicitGCInvokesConcurrent，但通过Btrace没有抓到System.gc的调用痕迹，可排除
2、JVM动态计算，并不是old gen占用率达到CMSInitiatingOccupancyFraction才进行回收
----设置了UseCMSInitiatingOccupancyOnly，可排除
3、当old gen的可用内存少于av_promo(每次次YGC时晋升到老年代对象大小的平均值)并且小于max_promotion_in_bytes(eden使用量+from使用量)时会触发
----小于max_promotion_in_bytes是有可能的，因为NewRatio=1，但少于av_promo的可能性太小，因为无法打印av_promo的值，写了一个分析gc日志计算晋升对象大小的程序，可排除
4、由permGen回收触发的
----没有设置CMSClassUnloadingEnabled，可排除
看上去好像都不满足触发CMS的条件，得从另外一个方向排查
【排查过程2】
查看concurrentMarkSweepThread的源码，关键点sleepBeforeNextCycle，意思是每个周期会调用一次shouldConcurrentCollect去判断是否需要执行CMS
而这个周期默认2秒，经检查测试环境设置的也是2秒，再看触发频率居然达到每秒2-3次！！远大于设置的2秒
因此，可以排除是由concurrentMarkSweepThread周期性触发的background式CMS，也和我们设置的CMSInitiatingOccupancyFraction没半点关系。
继续从源码追查，在genCollectedHeap中有一个GC的公共接口，关键点是should_do_concurrent_full_gc的判断
条件成立，会创建一个VM_GenCollectFullConcurrent的VM_operation，加到VMThread的队列中执行，可以看到System.gc()其中一种情况也是这样触发CMS进行并发回收的(另外一种情况是上述background式的CMS)
查看JVM参数，果然设置了GCLockerInvokesConcurrent (ExplicitGCInvokesConcurrent在上面已被排除)
于是屏蔽了GCLockerInvokesConcurrent进行反复测试，没有再发生过CMS了，而且触发YGC的GCLocker GCCause也涌现出来，至此，真相浮出水面
【小结与后续】
频繁触发CMS的原因找到了：设置了JVM参数GCLockerInvokesConcurrent
这里遗留了三个疑问：
(1)是什么JNI调用触发了gclocker
(2)什么情况下gclocker触发ygc还不够，要调用genCollectionHeap中的collect方法进行回收
(3)对于屏蔽掉GCLockerInvokesConcurrent的测试，ygc的频率随着时间不断增加，平均每秒2-3次(约等于之前的ygc+cms)，显然问题还是存在的，只是没有触发CMS
补充：
查看源码的时候，能看到initial和remark两个阶段会把cause回写，这也是为什么gccause只能看到CMS Initial Mark和CMS final Remark的原因吧
网友评论