在初步确定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很快的话可以考虑下这个选项，暂未实验.
文章转自庄周梦蝶 ，原文发布时间2009-09-22