Posted on 2009-09-26 18:29
dennis 阅读(2094)
评论(1) 编辑 收藏 所属分类:
java
本以为在上篇定稿的参数后应该能有比较好的表现，然后实际的表现大出我的意料，cms回收触发非常频繁，虽然每次都只是10-50毫秒，但是次数12个小时内能达到180多次，这显然不正常。通过gc日志和jstat可以看到，每次old区还在5%左右就开始进行CMS，此时的perm区也才30%，这两个数字有浮动并且CMS触发的时间上也没有规律，在测试环境和生产环境中都是如此。
那么最后是怎么解决的呢？其实没有解决。我只是替换了一个参数就没再发生这个现象，上文提到为了避免System.gc()调用引起的full gc，使用了jdk6引入的新参数-XX:+ExplicitGCInvokesConcurrent来让System.gc()并发执行，但是测试表明恰恰是这个参数引起了CMS的频繁发生，去掉这个参数就没有那个奇特的现象。重复检查了代码，并且再次查看了GC日志，没有再发现有System.gc()的调用，我暂时将原因归结于使用了ExplicitGCInvokesConcurrent参数后其他方法触发了CMS，如果有知晓的朋友请留言告知，最后的方案还是彻底禁掉了显式GC调用。最终定稿的参数：
-server -Xms1536m -Xmx1536m -XX:NewSize=256m -XX:MaxNewSize=256m
-XX:PermSize=64m -XX:MaxPermSize=64m -XX:+UseConcMarkSweepGC
-XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=70
-XX:+CMSParallelRemarkEnabled -XX:SoftRefLRUPolicyMSPerMB=0
-XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC
-XX:SurvivorRatio=8
删除了+CMSPermGenSweepingEnabled，这个参数在jdk6上跟-XX:+CMSClassUnloadingEnabled作用重叠了，如果你还跑在jdk5上面，那么应该使用这个参数。救助空间设置为NewSize的1/10，也就是25M左右，让年轻代尽量回收，防止年轻对象跑到年老代过早触发CMS甚至full gc。CMS的触发阀值下降到70%，因为年老代增长较慢，宁愿回收次数多一点，降低长暂停的可能。
24小时内的某台生产机器的表现，通过jstat观察：
S0 S1 E O P YGC YGCT FGC FGCT GCT
39.70 0.00 5.59 15.15 28.99 20260 326.041 14 0.592 326.633
39.70 0.00 65.49 15.15 28.99 20260 326.041 14 0.592 326.633
0.00 36.93 19.37 15.16 29.01 20261 326.059 14 0.592 326.650
0.00 36.93 93.23 15.16 29.01 20261 326.059 14 0.592 326.650
34.04 0.00 59.62 15.17 29.01 20262 326.076 14 0.592 326.668
0.00 38.55 12.76 15.19 29.01 20263 326.094 14 0.592 326.686
0.00 38.55 65.48 15.19 29.01 20263 326.094 14 0.592 326.686
CMS两次暂停时间总和在100ms以下，minor gc平均一次执行花了16ms，平均3-4秒发生一次。暂时来看还不错，也许还可以适当调小一下NewSize，加快以下minor gc。
此次调整总共花了大概一周多的时间，由于经验不足，还是走了不少弯路，幸好最终的结果还可以，也让自己对cms gc有比较深入的了解。我们的系统在周4晚上已经全部更新上线，从内部测试、压测、日常测试、beta测试以来，每个阶段都发现几个隐蔽的问题，在上线后暂时没有再发现问题，证明这个流程还是很有意义的，我过去对流程充满偏见，现在看来是可笑的。总结我在淘宝5个月越来学习到的东西，几个关键词：认真、负责、细心、快乐。