java GC調優

原帖地址：http://arbow.javaeye.com/blog/362861

由於Boss看了某JVM GC調整的文章，興緻大發叫嚷要對我們的服務進行調優，於是開始了一次調優經曆。

由於服務是屬於非後台計算類型，因此拋棄了並行回收策略，而使用並發回收，對年輕代做並行回收，年老代做並發回收，參數

引用-Xms2048m -Xmx2048m -Xmn512m -XX:ParallelGCThreads=8 -XX:+UseConcMarkSweepGC -Xloggc:/home/resin/logs/gc.log

這個配置，年輕代設定比較大，有512M，但問題不在於此。使用jstat做統計，發現幾乎所有的Full
GC都是在100ms以下完成，但是查看gc.log，卻發現裡面的Full GC都在幾秒，數量不多。這個gc
log跟jstat中的資料對不上。更糟糕的是，在高峰期，由於堆被大量佔用（疑似有記憶體流失），OU到了90%以上，FullGC相當頻繁，期間也出現
了幾次高達7s的停頓。Boss心慌慌，聽到有7s之後特著急，想著要是每次都7s，每分鐘來一次FullGC，那系統就有10%以上的時間得停止了~~

好了，碰到這種問題，有人第一時間想Java
的效能真爛，有人打算換JVM，估計還有人想著用C++重寫。

Stop！這屬於抓瞎行為，讓我們來分析下問題所在。

1.缺乏詳細日誌，這對調優來說，太重要了

2.資料樣本太少，服務僅僅運行了幾天，也沒有詳細的記錄，需要記錄資料。

3.使用CMS回收器，但是卻有幾條停頓時間超長的記錄，Why？

處理：

首先加入了更詳盡的日誌輸出

引用-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCTimeStamps -XX:+PrintGCDetails

資料採樣，將jstat -gcutil的結果記錄到日誌，以2000ms為間隔，記錄一個星期。

Concurrent mode failure：當cms並發回收期間，如果需要分配的記憶體不足，就會導致Stop All
World，進行一次大的回收，當年老代快暴滿的時候，很有可能發生。另外使用CMS回收會導致記憶體片段，也有可能導致運行一段時間之後由於片段問題而不
得不進行一次完整的GC。參數加入

引用-XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=80

設定每次回收時，壓縮記憶體片段，並且在年老代達到80%使用率時馬上進行回收。

最終將參數設定為

引用-Xms2048m
-Xmx2048m -Xmn384m -Xss256k -XX:PermSize=128M -XX:NewSize=384m
-XX:MaxNewSize=384m -XX:MaxPermSize=256m -XX:ParallelGCThreads=8
-XX:+UseConcMarkSweepGC -XX:+UseCMSCompactAtFullCollection
-XX:+CMSParallelRemarkEnabled -XX:CMSInitiatingOccupancyFraction=80
-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCTimeStamps
-XX:+PrintGCDetails -Xloggc:/home/resin/logs/gc.log

經過一周的觀察，有幾點值得注意。

1.在系統空閑時，會有時間較長的FullGC發生，而且此時年老代的佔用並沒有上80%，而且間隔時間很接近1個小時整。日誌輸出為類似

引用9654.793: [Full GC (System) 9654.793: [CMS: 1285124K->512456K(1703936K), 2.9613390 secs] 1340458K->512456K(2057856K), [C

MS Perm : 98053K->81932K(155480K)], 2.9617070 secs] [Times: user=2.94 sys=0.01, real=2.96 secs]

2.當系統有一定負載後，年老代佔用到80%會馬上進行cms gc，時間一般都很短，分2次停頓完成。日誌輸出類似

引用6047.709: [GC [1 CMS-initial-mark: 869803K(1703936K)] 909529K(2057856K), 0.0352070 secs] [Times: user=0.04 sys=0.00, rea

l=0.03 secs]

6047.745: [CMS-concurrent-mark-start]

6048.475: [CMS-concurrent-mark: 0.713/0.730 secs] [Times: user=1.64 sys=0.02, real=0.73 secs]

6048.475: [CMS-concurrent-preclean-start]

6048.486: [CMS-concurrent-preclean: 0.010/0.011 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

6048.486: [CMS-concurrent-abortable-preclean-start]

CMS: abort preclean due to time 6053.533: [CMS-concurrent-abortable-preclean: 2.835/5.047 secs] [Times: user=3.52 sys=0

.05, real=5.05 secs]

6053.533: [GC[YG occupancy: 205354 K (353920 K)]6053.533: [Rescan (parallel) , 0.1636670 secs]6053.697: [weak refs proce

ssing, 0.2716410 secs] [1 CMS-remark: 869803K(1703936K)] 1075158K(2057856K), 0.4361030 secs] [Times: user=0.57 sys=0.28,

real=0.44 secs]

6053.970: [CMS-concurrent-sweep-start]

6054.791: [CMS-concurrent-sweep: 0.810/0.821 secs] [Times: user=0.99 sys=0.01, real=0.82 secs]

6054.791: [CMS-concurrent-reset-start]

6054.802: [CMS-concurrent-reset: 0.010/0.010 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

3.使用jmap -histo做輸出，很可能會造成一次FullGC，停頓可能超過8s！不要在高峰期做這種操作，只使用jstat。

4.樣本資料分析。對jstat輸出的fgc時間進行分析，按小時段歸類，結果如下：

引用時刻總時間總次數平均停頓時間

03248.0ms5955.0508474576ms

12103.0ms3658.4166666667ms

211239.0ms20561.95ms

320596.0ms161287.25ms

431261.0ms142232.92857143ms

536141.0ms142581.5ms

634614.0ms142472.42857143ms

723626.0ms191243.47368421ms

814499.0ms31467.709677419ms

910341.0ms59175.271186441ms

1011063.0ms95116.452631579ms

118086.0ms11371.5575221239ms

1216305.0ms145112.448275862ms

136952.0ms16442.3902439024ms

147079.0ms17141.3976608187ms

158023.0ms19341.5699481865ms

1626697.0ms221120.800904977ms

1715841.0ms18685.1666666667ms

187092.0ms19835.8181818182ms

198373.0ms21139.682464455ms

208718.0ms22838.2368421053ms

218184.0ms21238.6037735849ms

226001.0ms15837.9810126582ms

235884.0ms9860.0408163265ms

要注意這裡的次數包含了每一次cms回收時的2次停頓，而且包含了由於少量jmap操作導致的誤差。

結論：

1.CMS回收器已經比較理想，能夠將1.5G的堆FullGC時間降到平均每次50ms左右。對於VOIP這些即時性要求更高的應用，可以期待
G1回收器。對應用來說，在輸送量和延遲之間，需要找到一個平衡點，CMS回收器這種延遲低的演算法，會導致輸送量下降。此外由於使用了
UseCMSCompactAtFullCollection參數，會導致效能有所下降。配置適當的
CMSFullGCsBeforeCompaction參數，可能有助於提高效能。

2.JVM會在伺服器空閑時定時進行非CMS的FullGC，時間平均在2s以上，通常發生於半夜。而且回收時，年老代尚未到
CMSInitiatingOccupancyFraction設定的值。但這種現象很少會發生，在伺服器繁忙時基本不會出現，對服務不會造成較大影響。

3.對Java
這種共用堆的GC而言，2G已經比較吃力。一般1G是較為理想的大小。儘可能使用多JVM進程叢集的方式來充分使用伺服器資源才是正道。（無法想象開8G的堆會發生什麼事情）

下一步再對jvm參數做調整，觀察效果。