CMS gc调整实践(续)?转载自 ---- http://www.blogjava.net/killme2008/archive/2009/09/22/296085.html???
CMS gc调整实践(续)
?
转载自 ---- http://www.blogjava.net/killme2008/archive/2009/09/22/296085.html
?
?????? 在初步确定CMS参数后，系统运行了几天，今天尝试在线上打开了GC日志，按阿宝同学的说法是gc日志的开销比之jstat还小，打开之后发现确实影响很小。打开GC日志之后又发现几个隐藏的问题比较有价值，这里记录下。
?? 首先是系统在启动的时候有一次System.gc()调用引起的full gc，日志输出类似这样：
1.201:?[Full?GC?(System)?1.201:?[CMS:?0K->797K(1310720K),?0.1090540?secs]?29499K->797K(1546688K),?[CMS?Perm?:?5550K->5547K(65536K)],?0.1091860?secs]?[Times:?user=0.05?sys=0.06,?real=0.11?secs]
?? 可以确认的是我们系统里的代码绝对没有调用System.gc()方法，但是不保证第三方代码有调用，通过搜索代码引用，后来定位到了mina的ByteBuffer创建上面。Mina 1.1封装的ByteBuffer的allocate()方法默认创建的是Direct ByteBuffer，而DirectByteBuffer的构造函数里调用了
Bits.reserveMemory(cap);
这个方法强制调用了System.gc():
static?void?reserveMemory(long?size)?{
????synchronized?(Bits.class)?{
????????if?(!memoryLimitSet?&&?VM.isBooted())?{
????????maxMemory?=?VM.maxDirectMemory();
????????memoryLimitSet?=?true;
????????}
????????if?(size?<=?maxMemory?-?reservedMemory)?{
????????reservedMemory?+=?size;
????????return;
????????}
????}
????
System.gc();????try?{
????????Thread.sleep(100);
????}?catch?(InterruptedException?x)?{
????????//?Restore?interrupt?status
????????Thread.currentThread().interrupt();
????}
????synchronized?(Bits.class)?{
????????if?(reservedMemory?+?size?>?maxMemory)
????????throw?new?OutOfMemoryError("Direct?buffer?memory");
????????reservedMemory?+=?size;
????}
????}
??? 调用这个方法是为了用户对Direct ByteBuffer的内存可控。而在我们系统中使用的通讯层初始化Decoder的时候通过Mina 1.1创建了一个Direct ByteBuffer，导致了这一次强制的full gc。这个Buffer因为是长期持有的，因此创建Direct类型也还可以接受。
??? 但是在这次GC后，又发现每隔一个小时就有一次System.gc()引起的full gc，这就太难以忍受了，日志大概是这样，注意间隔时间都是3600秒左右：
10570.672:?[Full?GC?(System)?10570.672:?[CMS:?779199K->107679K(1310720K),?1.2957430?secs]?872163K->107679K(1546688K),?[CMS?Perm?:?23993K->15595K(65536K)],?1.2959630?secs]?[Times:?user=1.27?sys=0.02,?real=1.30?secs]?
14171.971:?[Full?GC?(System)?14171.971:?[CMS:?680799K->83681K(1310720K),?1.0171580?secs]?836740K->83681K(1546688K),?[CMS?Perm?:?20215K->15599K(65536K)],?1.0173850?secs]?[Times:?user=0.97?sys=0.01,?real=1.02?secs]?
17774.020:?[Full?GC?(System)?17774.020:?[CMS:?676201K->79331K(1310720K),?0.9652670?secs]?817596K->79331K(1546688K),?[CMS?Perm?:?22808K->15619K(65536K)],?0.9655150?secs]?[Times:?user=0.93?sys=0.02,?real=0.97?secs]?
21374.989:?[Full?GC?(System)?21374.989:?[CMS:?677818K->78590K(1310720K),?0.9297080?secs]?822317K->78590K(1546688K),?[CMS?Perm?:?16435K->15593K(65536K)],?0.9299620?secs]?[Times:?user=0.89?sys=0.01,?real=0.93?secs]?
24976.948:?[Full?GC?(System)?24976.948:?[CMS:?659511K->77608K(1310720K),?0.9255360?secs]?794004K->77608K(1546688K),?[CMS?Perm?:?22359K->15594K(65536K)],?0.9257760?secs]?[Times:?user=0.88?sys=0.02,?real=0.93?secs]?
28578.892:?[Full?GC?(System)?28578.892:?[CMS:?562058K->77572K(1310720K),?0.8365500?secs]?735072K->77572K(1546688K),?[CMS?Perm?:?15840K->15610K(65536K)],?0.8367990?secs]?[Times:?user=0.82?sys=0.00,?real=0.84?secs]?
32179.731:?[Full?GC?(System)?32179.732:?[CMS:?549874K->77224K(1310720K),?0.7864400?secs]?561803K->77224K(1546688K),?[CMS?Perm?:?16016K->15597K(65536K)],?0.7866540?secs]?[Times:?user=0.75?sys=0.01,?real=0.79?secs]
??? 搜遍了源码和依赖库，没有再发现显式的gc调用，问题只能出在运行时上，突然想起我们的系统使用RMI暴露JMX给监控程序，监控程序通过RMI连接JMX监控系统和告警等，会不会是RMI的分布式垃圾收集导致的？果然，一查资料，RMI的分布式收集会强制调用System.gc()来进行分布式GC，server端的间隔恰好是一个小时，这个参数可以通过：
-Dsun.rmi.dgc.server.gcInterval=3600000
来调整。调长时间是一个解决办法，但是我们更希望能不出现显式的GC调用，禁止显式GC调用通过-XX:+DisableExplicitGC是一个办法，但是禁止了分布式GC会导致什么问题却是心理没底，毕竟我们的JMX调用还是很频繁的，幸运的是JDK6还提供了另一个选项-XX:+ExplicitGCInvokesConcurrent，允许System.gc()也并发运行，调整DGC时间间隔加上这个选项双管齐下彻底解决了full gc的隐患。
??? 打开GC日志后发现的另一个问题是remark的时间过长，已经启用了并行remark，但是时间还是经常超过200毫秒，这个可能的原因有两个：我们的年老代太大或者触发CMS的阀值太高了，CMS进行的时候年老代里的对象已经太多。初步的计划是调小-XX:SurvivorRatio增大救助空间并且降低-XX:CMSInitiatingOccupancyFraction这个阀值。此外，还找到另一个可选参数-XX:+CMSScavengeBeforeRemark，启用这个选项后，强制remark之前开始一次minor gc，减少remark的暂停时间，但是在remark之后也将立即开始又一次相对较长时间minor gc，如果你的minor gc很快的话可以考虑下这个选项，暂未实验。
