上次介紹了IBM的兩款分析gc log的工具（GCMV和PMAT），這次講講HP推出的HPjmeter。HPjmeter集成了以前的HPjtune功能，可以分析在HP機器上產生的垃圾回收日誌檔案。你可以到Hewlett-Packard Java website免費下載最新的4.0版本，當然會讓你填一些資訊。

接下來我將分析一個實際生產環境下的日誌檔案，這個生產系統在啟用新的功能後應用訪問速度變慢，每個操作都要耗時10s左右，通過對比前後不同的gc資訊，希望能從JVM的層面來優化當前的效能。

HP小機（Pa-Risc和安騰平臺）使用HP的JDK後，使用-Xloggc:filename或者-Xverbosegc:file=filename引數會生成形如

<GCH: vmrelease=”1.4.2 1.4.2.10-060112-16:07-PA_RISC2.0 PA2.0 (aCC_AP)
……
<GCH: mode=n >
<GCH: ncpu=8 >
<GCH: availswap=33554432 >
<GCH: usedswap=0 >
……
<GC: 2 4  9.625554 1 0 31 48539536 0 286392320 0 0 35782656 0 2409608 715849728 20971424 20971424 20971520 0.279391 0.279391 >
<GC: 2 4  10.879321 2 0 31 9797920 0 286392320 0 0 35782656 2409608 2742416 715849728 25165568 25165568 25165824 0.307422 0.307422 >

的日誌，這種格式人肉分析就別想了，它可以在PMAT中以Xverbosegc/hpux檔案格式開啟，但是圖象功能我這裡沒法使用，只好求助於HP自家的工具——HPjmeter了。

分析過程

用HPjmeter載入日誌檔案後，會自動開啟HPjtune的視窗。首先會看到Heap Usage After GC標籤頁，這是四月份正常的情況（請先忽略systemgc，這點留待後面分析）

下面是六月份速度慢的情況：

明顯能看到Old full（with perm）代表的黃點增多了，從之前的日誌檔案頭我們瞭解到這個系統所用的JDK為1.4.2 32位版本（64位版本會寫明Java VM name = Java HotSpot(TM) 64-Bit Server VM），預設的回收策略是序列收集器，在Old區發生垃圾回收時是Stop the world的full gc，每次full gc耗時基本在10s～12s

切換到”Summary”標籤頁

4月花在gc上的時間佔整個JVM執行時間的3.036%，Full GC佔整個JVM執行時間的0.993%，應該說是情況良好。

到了6月份，情況卻變化很大，時間分別為10.791%和8.417%，因為超過了5%的警戒線而顯示為紅色，而且79%的GC時間花在full gc上。

這還是一週的情況，包括了週末和晚間空閒時刻，讓我們看看在上班高峰期間的執行情況。

乖乖，有61%的時間花在gc上，速度不慢才怪了。我們檢視當前對應的Heap Usage After GC

除了開始的少數年輕代中發生的快速Scavenge，大部分都是慢速的Full GC，而且可以看到每次回收後使用的堆空間並沒有減小，反而越來越大，有記憶體洩漏的徵兆。不過堆空間並沒有一路增長下去直到OutOfMemory，而是像下圖般那樣反覆。

早上和下午兩個業務繁忙期全是full gc，效能表現很差，而4月正常的情況應是如此

Eden區滿了後，經過Scavenge動作一部分物件被轉移到了Old區，所以堆中佔用空間上升，直到Old區也無法分配了，那麼發生full gc，記憶體又重新回到一個較低的位置，這是正常的情況。現在6月份出現一直Full GC也無法回收，但又沒有發生OutOfMemory，可以判斷為原來設定的引數無法滿足新內容投產後的需求

例如沒有使用並行回收，沒有發揮8個CPU的效果，沒有采用低響應時間的CMS回收模式。

同時新系統產生的物件數量也大大增加，從四月一天的500000個增加到900000個（左邊四月，右邊六月）。

導致每次回收後，從新生代轉移到年老區的物件數量也變多，其實它們並非是長存物件，只是新生代暫時無法容納下它們了。

而且full gc會導致Survivor區裡的所有物件都被轉移到old區，這造成了惡性迴圈。（黃色的Full GC後，Survivor裡的物件為零）

優化操作

調整目標：儘可能的將短時間存活的物件在年輕代就能被丟棄掉，而不要轉移到年老代中；採用並行回收方式增加效率；避免產生不必要的Full GC；或者採用響應時間短的垃圾回收方式。

調整方法：增大年輕代大小，減小SurvivorRatio加大Survivor區（也就是From or To）；設定並行回收引數;設定初始堆和最大堆為同樣值、設定初始PermSize為一個合理值，避免執行過程中增長；設定回收策略為CMS。

引數設定一：-Xms1500m -Xmx1500m -Xmn800m -XX:SurvivorRatio=4 -XX:PermSize=160m  -XX:+UseParallelGC（-XX:ParallelGCThreads=8我覺得可以不用顯示的宣告，可以再上述引數設定後分析新的gc log，看一下System Details頁面中ParallelGCThreads的數目再做定奪，1.4.2的JDK不能再Old區做並行回收，也是一個遺憾）

引數設定二：-Xms1500m -Xmx1500m -Xmn800m -XX:PermSize=160m  -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:CMSFullGCsBeforeCompaction=5（或者最後一個引數設定為-XX:+UseCMSCompactAtFullCollection）

後續進展

引數設定後還有一個觀察過程，如果效果不佳，那從系統整合的角度，一是更換64位JDK，這樣可以設定更大的堆空間（不過WebSphere更換JDK不像Weblogic那麼簡單，如果沒有買過64位WebSphere的話只好作罷）；二是啟用WebSphere的叢集，但這需要ND版本的WAS。

從應用的角度，可以在早上8點做一次heapdump，9點半做一次heapdump，分析一下full gc記憶體回收不下來的原因，確定不是程式的錯誤造成的。或者啟用-agentlib:hprof引數，用HPjmeter來trace應用的表現、用HPjmeter來直接監控應用的執行情況。不過這兩個方法對效能影響較大，要在測試環境下進行。

其它的一些碎碎念

現在我們來說說日誌中那麼多的systemgc，剛開始看到我大吃一驚，但放大影象後發現這些自行呼叫的full gc都是下班後做的，應該是另一個應用觸發的，對白天的效能影響應該不大。

不過這裡還是要再申明一句：自行呼叫System.gc（）函式會損害到JVM的效能，因為這時候是Stop the World的回收，消耗的時間長，但效果並非最佳。你也許會認為你對程式很熟悉，可以在空閒的時間執行system.gc，不會影響到客戶訪問，但是正如之前所說，full gc後survivor裡的所有內容都被轉移到了old區長久儲存，所以在某個將來，JVM就不得不因為這個原因再做一次不必要的full gc。

IBM JDK下避免主動回收的引數是“-Xdisableexplicitgc”，Sun JDK下的引數是“-XX:+DisableExplicitGC”，注意區別。

備註：