用HPjtune分析GC日志（一個(gè)實(shí)際案例的診斷過(guò)程）
上次介紹了IBM的兩款分析gc log的工具（GCMV和PMAT），這次講講HP推出的HPjmeter。HPjmeter集成了以前的HPjtune功能，可以分析在HP機器上產(chǎn)生的垃圾回收日志文件。你可以到Hewlett-Packard Java website免費下載最新的4.0版本，當然會(huì )讓你填一些信息。
接下來(lái)我將分析一個(gè)實(shí)際生產(chǎn)環(huán)境下的日志文件，這個(gè)生產(chǎn)系統在啟用新的功能后應用訪(fǎng)問(wèn)速度變慢，每個(gè)操作都要耗時(shí)10s左右，通過(guò)對比前后不同的gc信息，希望能從JVM的層面來(lái)優(yōu)化當前的性能。
HP小機（Pa-Risc和安騰平臺）使用HP的JDK后，使用-Xloggc:filename或者-Xverbosegc:file=filename參數會(huì )生成形如
……
<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文件格式打開(kāi)，但是圖象功能我這里沒(méi)法使用，只好求助于HP自家的工具——HPjmeter了。
分析過(guò)程
用HPjmeter加載日志文件后，會(huì )自動(dòng)打開(kāi)HPjtune的窗口。首先會(huì )看到Heap Usage After GC標簽頁(yè)，這是四月份正常的情況（請先忽略systemgc，這點(diǎn)留待后面分析）
下面是六月份速度慢的情況：
明顯能看到Old full（with perm）代表的黃點(diǎn)增多了，從之前的日志文件頭我們了解到這個(gè)系統所用的JDK為1.4.2 32位版本（64位版本會(huì )寫(xiě)明Java VM name = Java HotSpot(TM) 64-Bit Server VM），默認的回收策略是串行收集器，在Old區發(fā)生垃圾回收時(shí)是Stop the world的full gc，每次full gc耗時(shí)基本在10s～12s
切換到”Summary”標簽頁(yè)
4月花在gc上的時(shí)間占整個(gè)JVM運行時(shí)間的3.036%，Full GC占整個(gè)JVM運行時(shí)間的0.993%，應該說(shuō)是情況良好。
到了6月份，情況卻變化很大，時(shí)間分別為10.791%和8.417%，因為超過(guò)了5%的警戒線(xiàn)而顯示為紅色，而且79%的GC時(shí)間花在full gc上。
這還是一周的情況，包括了周末和晚間空閑時(shí)刻，讓我們看看在上班高峰期間的運行情況。
乖乖，有61%的時(shí)間花在gc上，速度不慢才怪了。我們查看當前對應的Heap Usage After GC
除了開(kāi)始的少數年輕代中發(fā)生的快速Scavenge，大部分都是慢速的Full GC，而且可以看到每次回收后使用的堆空間并沒(méi)有減小，反而越來(lái)越大，有內存泄漏的征兆。不過(guò)堆空間并沒(méi)有一路增長(cháng)下去直到OutOfMemory，而是像下圖般那樣反復。
早上和下午兩個(gè)業(yè)務(wù)繁忙期全是full gc，性能表現很差，而4月正常的情況應是如此
Eden區滿(mǎn)了后，經(jīng)過(guò)Scavenge動(dòng)作一部分對象被轉移到了Old區，所以堆中占用空間上升，直到Old區也無(wú)法分配了，那么發(fā)生full gc，內存又重新回到一個(gè)較低的位置，這是正常的情況?，F在6月份出現一直Full GC也無(wú)法回收，但又沒(méi)有發(fā)生OutOfMemory，可以判斷為原來(lái)設置的參數無(wú)法滿(mǎn)足新內容投產(chǎn)后的需求
例如沒(méi)有使用并行回收，沒(méi)有發(fā)揮8個(gè)CPU的效果，沒(méi)有采用低響應時(shí)間的CMS回收模式。
同時(shí)新系統產(chǎn)生的對象數量也大大增加，從四月一天的500000個(gè)增加到900000個(gè)（左邊四月，右邊六月）。
導致每次回收后，從新生代轉移到年老區的對象數量也變多，其實(shí)它們并非是長(cháng)存對象，只是新生代暫時(shí)無(wú)法容納下它們了。
而且full gc會(huì )導致Survivor區里的所有對象都被轉移到old區，這造成了惡性循環(huán)。（黃色的Full GC后，Survivor里的對象為零）
優(yōu)化操作
調整目標：盡可能的將短時(shí)間存活的對象在年輕代就能被丟棄掉，而不要轉移到年老代中；采用并行回收方式增加效率；避免產(chǎn)生不必要的Full GC；或者采用響應時(shí)間短的垃圾回收方式。
調整方法：增大年輕代大小，減小SurvivorRatio加大Survivor區（也就是From or To）；設置并行回收參數;設置初始堆和最大堆為同樣值、設置初始PermSize為一個(gè)合理值，避免運行過(guò)程中增長(cháng)；設置回收策略為CMS。
參數設置一：-Xms1500m -Xmx1500m -Xmn800m -XX:SurvivorRatio=4 -XX:PermSize=160m -XX:+UseParallelGC（-XX:ParallelGCThreads=8我覺(jué)得可以不用顯示的聲明，可以再上述參數設置后分析新的gc log，看一下System Details頁(yè)面中ParallelGCThreads的數目再做定奪，1.4.2的JDK不能再Old區做并行回收，也是一個(gè)遺憾）
參數設置二：-Xms1500m -Xmx1500m -Xmn800m -XX:PermSize=160m -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:CMSFullGCsBeforeCompaction=5（或者最后一個(gè)參數設置為-XX:+UseCMSCompactAtFullCollection）
上述參數的意義可以看《JAVA性能優(yōu)化—Sun Hotspot JDK JVM參數設置》
后續進(jìn)展
參數設置后還有一個(gè)觀(guān)察過(guò)程，如果效果不佳，那從系統集成的角度，一是更換64位JDK，這樣可以設置更大的堆空間（不過(guò)WebSphere更換JDK不像Weblogic那么簡(jiǎn)單，如果沒(méi)有買(mǎi)過(guò)64位WebSphere的話(huà)只好作罷）；二是啟用WebSphere的集群，但這需要ND版本的WAS。
從應用的角度，可以在早上8點(diǎn)做一次heapdump，9點(diǎn)半做一次heapdump，分析一下full gc內存回收不下來(lái)的原因，確定不是程序的錯誤造成的?；蛘邌⒂?agentlib:hprof參數，用HPjmeter來(lái)trace應用的表現、用HPjmeter來(lái)直接監控應用的運行情況。不過(guò)這兩個(gè)方法對性能影響較大，要在測試環(huán)境下進(jìn)行。
其它的一些碎碎念
現在我們來(lái)說(shuō)說(shuō)日志中那么多的systemgc，剛開(kāi)始看到我大吃一驚，但放大圖像后發(fā)現這些自行調用的full gc都是下班后做的，應該是另一個(gè)應用觸發(fā)的，對白天的性能影響應該不大。
不過(guò)這里還是要再申明一句：自行調用System.gc（）函數會(huì )損害到JVM的性能，因為這時(shí)候是Stop the World的回收，消耗的時(shí)間長(cháng)，但效果并非最佳。你也許會(huì )認為你對程序很熟悉，可以在空閑的時(shí)間執行system.gc，不會(huì )影響到客戶(hù)訪(fǎng)問(wèn)，但是正如之前所說(shuō)，full gc后survivor里的所有內容都被轉移到了old區長(cháng)久保存，所以在某個(gè)將來(lái)，JVM就不得不因為這個(gè)原因再做一次不必要的full gc。
IBM JDK下避免主動(dòng)回收的參數是“-Xdisableexplicitgc”，Sun JDK下的參數是“-XX:+DisableExplicitGC”，注意區別。
