在初步確定CMS參數(shù)后，系統(tǒng)運(yùn)行了幾天，今天嘗試在線上打開了GC日志，按阿寶同學(xué)的說法是gc日志的開銷比之jstat還小，打開之后發(fā)現(xiàn)確實(shí)影響很小。打開GC日志之后又發(fā)現(xiàn)幾個(gè)隱藏的問題比較有價(jià)值，這里記錄下。
首先是系統(tǒng)在啟動(dòng)的時(shí)候有一次System.gc()調(diào)用引起的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]
可以確認(rèn)的是我們系統(tǒng)里的代碼絕對(duì)沒有調(diào)用System.gc()方法，但是不保證第三方代碼有調(diào)用，通過搜索代碼引用，后來定位到了mina的ByteBuffer創(chuàng)建上面。
Mina 1.1封裝的ByteBuffer的allocate()方法默認(rèn)創(chuàng)建的是Direct ByteBuffer，而DirectByteBuffer的構(gòu)造函數(shù)里調(diào)用了
Bits.reserveMemory(cap);
這個(gè)方法強(qiáng)制調(diào)用了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;
}
}
調(diào)用這個(gè)方法是為了用戶對(duì)Direct ByteBuffer的內(nèi)存可控。而在我們系統(tǒng)中使用的通訊層初始化Decoder的時(shí)候通過Mina 1.1創(chuàng)建了一個(gè)Direct ByteBuffer，導(dǎo)致了這一次強(qiáng)制的full gc。這個(gè)Buffer因?yàn)槭情L期持有的，因此創(chuàng)建Direct類型也還可以接受。
但是在這次GC后，又發(fā)現(xiàn)每隔一個(gè)小時(shí)就有一次System.gc()引起的full gc，這就太難以忍受了，日志大概是這樣，注意間隔時(shí)間都是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]
搜遍了源碼和依賴庫，沒有再發(fā)現(xiàn)顯式的gc調(diào)用，問題只能出在運(yùn)行時(shí)上，突然想起我們的系統(tǒng)使用RMI暴露JMX給監(jiān)控程序，監(jiān)控程序通過RMI連接JMX監(jiān)控系統(tǒng)和告警等，會(huì)不會(huì)是
RMI的分布式垃圾收集導(dǎo)致的？果然，一查資料，RMI的分布式收集會(huì)強(qiáng)制調(diào)用System.gc()來進(jìn)行分布式GC，server端的間隔恰好是一個(gè)小時(shí)，這個(gè)參數(shù)可以通過：
-Dsun.rmi.dgc.server.gcInterval=3600000
來調(diào)整。調(diào)長時(shí)間是一個(gè)解決辦法，但是我們更希望能不出現(xiàn)顯式的GC調(diào)用，禁止顯式GC調(diào)用通過
-XX:+DisableExplicitGC是一個(gè)辦法，但是禁止了分布式GC會(huì)導(dǎo)致什么問題卻是心理沒底，畢竟我們的JMX調(diào)用還是很頻繁的，幸運(yùn)的是JDK6還提供了另一個(gè)選項(xiàng)-XX:+ExplicitGCInvokesConcurrent，允許System.gc()也并發(fā)運(yùn)行，調(diào)整DGC時(shí)間間隔加上這個(gè)選項(xiàng)雙管齊下徹底解決了full gc的隱患。
打開GC日志后發(fā)現(xiàn)的另一個(gè)問題是remark的時(shí)間過長，已經(jīng)啟用了并行remark，但是時(shí)間還是經(jīng)常超過200毫秒，這個(gè)可能的原因有兩個(gè)：我們的年老代太大或者觸發(fā)CMS的閥值太高了，CMS進(jìn)行的時(shí)候年老代里的對(duì)象已經(jīng)太多。初步的計(jì)劃是調(diào)小-XX:SurvivorRatio增大救助空間并且降低-XX:CMSInitiatingOccupancyFraction這個(gè)閥值。此外，還找到另一個(gè)可選參數(shù)
-XX:+CMSScavengeBeforeRemark，啟用這個(gè)選項(xiàng)后，強(qiáng)制remark之前開始一次minor gc，減少remark的暫停時(shí)間，但是在remark之后也將立即開始又一次相對(duì)較長時(shí)間minor gc，如果你的minor gc很快的話可以考慮下這個(gè)選項(xiàng)，暫未實(shí)驗(yàn)。