jvm的GC日誌分析 [轉]

 

jvm的GC日誌分析

標籤： jvm內存javagc

2015-06-22 16:37  1566人閱讀  評論(1)  收藏  舉報

  分類：

Java（4） 

JVM的GC日誌的主要參數包括以下幾個：

-XX:+PrintGC 輸出GC日誌

-XX:+PrintGCDetails 輸出GC的詳細日誌

-XX:+PrintGCTimeStamps 輸出GC的時間戳（以基準時間的形式）

-XX:+PrintGCDateStamps 輸出GC的時間戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）

-XX:+PrintHeapAtGC 在進行GC的先後打印出堆的信息

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

-Xloggc:../logs/gc.log 日誌文件的輸出路徑

經常使用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。

在我作了以下的設置

-XX:+PrintGCDetails -Xloggc:../logs/gc.log -XX:+PrintGCTimeStamps

之後打印出來的日誌爲：

0.756: [Full GC (System) 0.756: [CMS: 0K->1696K(204800K), 0.0347096 secs] 11488K->1696K(252608K), [CMS Perm : 10328K->10320K(131072K)], 0.0347949 secs] [Times: user=0.06 sys=0.00, real=0.05 secs]
1.728: [GC 1.728: [ParNew: 38272K->2323K(47808K), 0.0092276 secs] 39968K->4019K(252608K), 0.0093169 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2.642: [GC 2.643: [ParNew: 40595K->3685K(47808K), 0.0075343 secs] 42291K->5381K(252608K), 0.0075972 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
4.349: [GC 4.349: [ParNew: 41957K->5024K(47808K), 0.0106558 secs] 43653K->6720K(252608K), 0.0107390 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
5.617: [GC 5.617: [ParNew: 43296K->7006K(47808K), 0.0136826 secs] 44992K->8702K(252608K), 0.0137904 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
7.429: [GC 7.429: [ParNew: 45278K->6723K(47808K), 0.0251993 secs] 46974K->10551K(252608K), 0.0252421 secs]

咱們取倒數第二條記錄分析一下各個字段都表明了什麼含義

5.617（時間戳）: [GC（Young GC） 5.617（時間戳）: [ParNew（GC的區域）: 43296K（垃圾回收前的大小）->7006K（垃圾回收之後的大小）(47808K)（該區域總大小）, 0.0136826 secs（回收時間）] 44992K（堆區垃圾回收前的大小）->8702K（堆區垃圾回收後的大小）(252608K)（堆區總大小）, 0.0137904 secs（回收時間）] [Times: user=0.03（GC用戶耗時） sys=0.00（GC系統耗時）, real=0.02 secs（GC實際耗時）]

咱們再對數據作一個簡單的分析

從最後一條GC記錄中咱們能夠看到 Young GC回收了 45278-6723=38555K的內存

Heap區經過此次回收總共減小了 46974-10551=36423K的內存。

38555-36423=2132K說明經過該次Young GC有2132K的內存被移動到了Old Gen，

 

咱們來驗證一下

在最後一次Young GC的回收之前 Old Gen的大小爲8702-7006=1696

回收之後Old Gen的內存使用爲10551-6723=3828

Old Gen在該次Young GC之後內存增長了3828-1696=2132K 與預計的相符

4.231: [GC 4.231: [DefNew: 4928K->512K(4928K), 0.0044047 secs] 6835K->3468K(15872K), 0.0045291 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4.445: [Full GC (System) 4.445: [Tenured: 2956K->3043K(10944K), 0.1869806 secs] 4034K->3043K(15872K), [Perm : 3400K->3400K(12288K)], 0.1870847 secs] [Times: user=0.05 sys=0.00, real=0.19 secs]

最前面的數字 4.231 和 4.445 表明虛擬機啓動以來的秒數。

[GC 和 [Full GC 是垃圾回收的停頓類型，而不是區分是新生代仍是年老代，若是有 Full 說明發生了Stop-The-World 。若是是調用 System.gc() 觸發的，那麼將顯示的是 [Full GC (System) 。

接下來的 [DefNew, [Tenured, [Perm 表示 GC 發生的區域，區域的名稱與使用的 GC 收集器相關。
Serial 收集器中新生代名爲 「Default New Generation」，顯示的名字爲 「[DefNew」。對於ParNew收集器，顯示的是 「[ParNew」，表示 「Parallel New Generation」。 對於 Parallel Scavenge 收集器，新生代名爲 「PSYoungGen」。年老代和永久代也相同，名稱都由收集器決定。

方括號內部顯示的 「4928K->512K(4928K)」 表示 「GC 前該區域已使用容量 -> GC 後該區域已使用容量 (該區域內存總容量) 」。

再日後的 「0.0044047 secs」 表示該區域GC所用時間，單位是秒。

再日後的 「6835K->3468K(15872K)」 表示 「GC 前Java堆已使用容量 -> GC後Java堆已使用容量 （Java堆總容量）」。

再日後的 「0.0045291 secs」 是Java堆GC所用的總時間。

最後的 「[Times: user=0.00 sys=0.00, real=0.00 secs]」 分別表明 用戶態消耗的CPU時間、內核態消耗的CPU時間 和 操做從開始到結束所通過的牆鍾時間。牆鍾時間包括各類非運算的等待耗時，如IO等待、線程阻塞。CPU時間不包括等待時間，當系統有多核時，多線程操做會疊加這些CPU時間，因此user或sys時間會超過real時間。

堆的分代

• young區域就是新生代，存放新建立對象；
• tenured是年老代，存放在新生代經歷屢次垃圾回收後仍存活的對象；
• perm是永生代，存放類定義信息、元數據等信息。

當GC發生在新生代時，稱爲Minor GC，次收集；當GC發生在年老代時，稱爲Major GC，主收集。 通常的，Minor GC的發生頻率要比Major GC高不少。

從新設置GC日誌的輸出

-XX:+PrintGCDetails
-XX:+PrintHeapAtGC
-XX:+PrintGCDateStamps
-XX:+PrintTenuringDistribution
-verbose:gc
-Xloggc:gc.log

後能夠看到進行GC先後的堆內存信息 

{Heap before GC invocations=1 (full 0):
 PSYoungGen      total 152896K, used 131072K [0x00000000f5560000, 0x0000000100000000, 0x0000000100000000)
  eden space 131072K, 100% used [0x00000000f5560000,0x00000000fd560000,0x00000000fd560000)
  from space 21824K, 0% used [0x00000000feab0000,0x00000000feab0000,0x0000000100000000)
  to   space 21824K, 0% used [0x00000000fd560000,0x00000000fd560000,0x00000000feab0000)
 PSOldGen        total 349568K, used 0K [0x00000000e0000000, 0x00000000f5560000, 0x00000000f5560000)
  object space 349568K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000f5560000)
 PSPermGen       total 26432K, used 26393K [0x00000000d0000000, 0x00000000d19d0000, 0x00000000e0000000)
  object space 26432K, 99% used [0x00000000d0000000,0x00000000d19c64a0,0x00000000d19d0000)
2013-05-05T23:16:10.480+0800: 5.228: [GC
Desired survivor size 22347776 bytes, new threshold 7 (max 15)
 [PSYoungGen: 131072K->8319K(152896K)] 131072K->8319K(502464K), 0.0176346 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
Heap after GC invocations=1 (full 0):
 PSYoungGen      total 152896K, used 8319K [0x00000000f5560000, 0x0000000100000000, 0x0000000100000000)
  eden space 131072K, 0% used [0x00000000f5560000,0x00000000f5560000,0x00000000fd560000)
  from space 21824K, 38% used [0x00000000fd560000,0x00000000fdd7ff78,0x00000000feab0000)
  to   space 21824K, 0% used [0x00000000feab0000,0x00000000feab0000,0x0000000100000000)
 PSOldGen        total 349568K, used 0K [0x00000000e0000000, 0x00000000f5560000, 0x00000000f5560000)
  object space 349568K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000f5560000)
 PSPermGen       total 26432K, used 26393K [0x00000000d0000000, 0x00000000d19d0000, 0x00000000e0000000)
  object space 26432K, 99% used [0x00000000d0000000,0x00000000d19c64a0,0x00000000d19d0000)
}

[0x00000000f5560000,0x00000000f5560000,0x00000000fd560000)

這種形式的日誌有兩種意義： 
當這種日誌出如今generation的詳細信息裏的時候，三個數字在HotSpot裏分別稱爲low_boundary、high、high_boundary。 
low_boundary: reserved space的最低地址邊界；一般也跟「low」相等，這是commited space的最低地址邊界 
high: commited space的最高地址邊界 
high_boundary: reserved space的最高地址邊界。 

[low_boundary, high_boundary)範圍內的就是reserved space，這個space的大小就是max capacity。 
[low, high)範圍內的就是commited space，而這個space的大小就是current capacity（當前容量），簡稱capacity。 
capacity有可能在一對最小值和最大值之間浮動。最大值就是上面說的max capacity。 

Gc日誌分析工具

(1)GCHisto
http://java.net/projects/gchisto
直接點擊gchisto.jar就能夠運行，點add載入gc.log
統計了總共gc次數，youngGC次數，FullGC次數，次數的百分比，GC消耗的時間，百分比，平均消耗時間，消耗時間最小最大值等

(2)GCLogViewer
http://code.google.com/p/gclogviewer/
點擊run.bat運行
整個過程gc狀況的趨勢圖，還顯示了gc類型，吞吐量，平均gc頻率，內存變化趨勢等
Tools裏還能比較不一樣gc日誌

參考文章：

http://swcdxd.iteye.com/blog/1859858

http://qa.blog.163.com/blog/static/19014700220128199421589/

http://coderbee.net/index.php/jvm/20131216/646

來源： http://blog.csdn.net/doc_sgl/article/details/46594123

來自爲知筆記(Wiz)