HPjmeter集成了以前的HPjtune功能,可以分析在HP機器上產生的垃圾回收日志文件。你可以到 Hewlett-Packard Java website 免費下載最新的4.0版本,當然會讓你填一些信息。
接下來我將分析一個實際生產環境下的日志文件,這個生產系統在啟用新的功能后應用訪問速度變慢,每個操作都要耗時10s左右,通過對比前后不同的gc信息,希望能從JVM的層面來優化當前的性能。
HP小機(Pa-Risc和安騰平臺)使用HP的JDK后,使用-Xloggc:filename或者-Xverbosegc:file=filename參數會生成形如
……
<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)
上述參數的意義可以看 《JAVA性能優化—Sun Hotspot JDK JVM參數設置》
后續進展
參數設置后還有一個觀察過程,如果效果不佳,那從系統集成的角度,一是更換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 ”,注意區別。
?
?
轉載 http://www.hashei.me/2009/07/use-hpjtune-to-analysis-gc-log.html
更多文章、技術交流、商務合作、聯系博主
微信掃碼或搜索:z360901061

微信掃一掃加我為好友
QQ號聯系: 360901061
您的支持是博主寫作最大的動力,如果您喜歡我的文章,感覺我的文章對您有幫助,請用微信掃描下面二維碼支持博主2元、5元、10元、20元等您想捐的金額吧,狠狠點擊下面給點支持吧,站長非常感激您!手機微信長按不能支付解決辦法:請將微信支付二維碼保存到相冊,切換到微信,然后點擊微信右上角掃一掃功能,選擇支付二維碼完成支付。
【本文對您有幫助就好】元
