GC之七--gc日志分析工具

本文轉載自查看原文 2016-11-23 11:10 12738 jvm-monitor/ gc/ JVM虛擬機/ 性能分析及調優

性能測試排查定位問題，分析調優過程中，會遇到要分析gc日志，人肉分析gc日志有時比較困難，相關圖形化或命令行工具可以有效地幫助輔助分析。

Gc日志參數

通過在tomcat啟動腳本中添加相關參數生成gc日志

-verbose.gc開關可顯示GC的操作內容。打開它，可以顯示最忙和最空閑收集行為發生的時間、收集前后的內存大小、收集需要的時間等。

打開-xx:+ printGCdetails開關，可以詳細了解GC中的變化。

打開-XX: + PrintGCTimeStamps開關，可以了解這些垃圾收集發生的時間，自JVM啟動以后以秒計量。

最后，通過-xx: + PrintHeapAtGC開關了解堆的更詳細的信息。

為了了解新域的情況，可以通過-XX:=PrintTenuringDistribution開關了解獲得使用期的對象權。

-Xloggc:$CATALINA_BASE/logs/gc.log gc日志產生的路徑

XX:+PrintGCApplicationStoppedTime // 輸出GC造成應用暫停的時間

-XX:+PrintGCDateStamps // GC發生的時間信息

Gc日志

2016-11-23T11:01:27.738+0800: 0.150: [GC [PSYoungGen: 331K->288K(5952K)] 331K->288K(19648K), 0.0006495 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2016-11-23T11:01:27.739+0800: 0.152: [Full GC (System) [PSYoungGen: 288K->0K(5952K)] [PSOldGen: 0K->164K(13696K)] 288K->164K(19648K) [PSPermGen: 3054K->3054K(21248K)], 0.0059625 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2016-11-23T11:01:27.852+0800: 0.264: [GC [PSYoungGen: 103K->64K(5952K)] 267K->228K(19648K), 0.0066830 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2016-11-23T11:01:27.859+0800: 0.271: [Full GC (System) [PSYoungGen: 64K->0K(5952K)] [PSOldGen: 164K->165K(13696K)] 228K->165K(19648K) [PSPermGen: 3060K->3060K(21248K)], 0.0052429 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

日志中顯示了gc發生的時間，young區回收情況，整體回收情況，fullGC情況，回收所消耗時間等.

常用JVM參數

分析gc日志后，經常需要調整jvm內存相關參數，常用參數如下

-Xms：初始堆大小，默認為物理內存的1/64(<1GB)；默認(MinHeapFreeRatio參數可以調整)空余堆內存小於40%時，JVM就會增大堆直到-Xmx的最大限制

-Xmx：最大堆大小，默認(MaxHeapFreeRatio參數可以調整)空余堆內存大於70%時，JVM會減少堆直到 -Xms的最小限制

-Xmn：新生代的內存空間大小，注意：此處的大小是（eden+ 2 survivor space)。與jmap -heap中顯示的New gen是不同的。整個堆大小=新生代大小 + 老生代大小 + 永久代大小。
在保證堆大小不變的情況下，增大新生代后,將會減小老生代大小。此值對系統性能影響較大,Sun官方推薦配置為整個堆的3/8。

-XX:SurvivorRatio：新生代中Eden區域與Survivor區域的容量比值，默認值為8。兩個Survivor區與一個Eden區的比值為2:8,一個Survivor區占整個年輕代的1/10。

-Xss：每個線程的堆棧大小。JDK5.0以后每個線程堆棧大小為1M,以前每個線程堆棧大小為256K。應根據應用的線程所需內存大小進行適當調整。在相同物理內存下,減小這個值能生成更多的線程。但是操作系統對一個進程內的線程數還是有限制的，不能無限生成，經驗值在3000~5000左右。一般小的應用，如果棧不是很深，應該是128k夠用的，大的應用建議使用256k。這個選項對性能影響比較大，需要嚴格的測試。和threadstacksize選項解釋很類似,官方文檔似乎沒有解釋,在論壇中有這樣一句話:"-Xss is translated in a VM flag named ThreadStackSize”一般設置這個值就可以了。

-XX:PermSize：設置永久代(perm gen)初始值。默認值為物理內存的1/64。

-XX:MaxPermSize：設置持久代最大值。物理內存的1/4。

Gc日志分析工具

(1)GCHisto

http://java.net/projects/gchisto

優點：可以橫向對比，如jvm參數調整前和調整后進行對比等。

直接點擊gchisto.jar就可以運行，點add載入gc.log

統計了總共gc次數，youngGC次數，FullGC次數，次數的百分比，GC消耗的時間，百分比，平均消耗時間，消耗時間最小最大值等

示例： jdk1.6，jvm參數為：-Xmx20m -XX:MaxDirectMemorySize=10m -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:gc1.6.log

2016-11-23T11:01:27.738+0800: 0.150: [GC [PSYoungGen: 331K->288K(5952K)] 331K->288K(19648K), 0.0006495 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2016-11-23T11:01:27.739+0800: 0.152: [Full GC (System) [PSYoungGen: 288K->0K(5952K)] [PSOldGen: 0K->164K(13696K)] 288K->164K(19648K) [PSPermGen: 3054K->3054K(21248K)], 0.0059625 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2016-11-23T11:01:27.852+0800: 0.264: [GC [PSYoungGen: 103K->64K(5952K)] 267K->228K(19648K), 0.0066830 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2016-11-23T11:01:27.859+0800: 0.271: [Full GC (System) [PSYoungGen: 64K->0K(5952K)] [PSOldGen: 164K->165K(13696K)] 228K->165K(19648K) [PSPermGen: 3060K->3060K(21248K)], 0.0052429 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

GCHisto展示：