在初步確定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很快的話可以考慮下這個選項，暫未實驗。