GC日誌分析

JVM的GC日誌的主要參數包含例如如下幾個：

-XX:+PrintGC 輸出GC日誌

-XX:+PrintGCDetails 輸出GC的具體日誌

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

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

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

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

在我作了例如如下的設置

-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（使用ParNew做爲年輕代的垃圾回收期）: 43296K（年輕代垃圾回收前的大小）->7006K（年輕代垃圾回收之後的大小）(47808K)（年輕代的總大小）, 0.0136826 secs（回收時間）] 44992K（堆區垃圾回收前的大小）->8702K（堆區垃圾回收後的大小）(252608K)（堆區總大小）, 0.0137904 secs（回收時間）] [Times: user=0.03（Young GC用戶耗時） sys=0.00（Young GC系統耗時）, real=0.02 secs（Young 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 與估計的相符

 

又一次設置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。 

轉載地址：http://swcdxd.iteye.com/blog/1859858