JVM調優日誌解析分析

1、調優參數設置

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 日誌文件的輸出路徑

 

分析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)
 
}

 

能夠看出先後回收掉了 131072K -  21824K*0.38  = 122778K 內存

示例代碼

/**
 * VM agrs: -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails
 * -XX:SurvivorRatio=8 -XX:+UseSerialGC
 */

public class MinorGCTest {
    private static final int _1MB = 1024 * 1024;

    public static void testAllocation() {
        byte[] allocation1, allocation2, allocation3, allocation4;
        allocation1 = new byte[2 * _1MB];
        allocation2 = new byte[2 * _1MB];
        allocation3 = new byte[2 * _1MB];
        allocation4 = new byte[4 * _1MB];
    }

    public static void main(String[] agrs) {
        testAllocation();
    }
}

 

• VM參數說明

Option	Description
-verbose:gc	顯示GC的操做內容
-Xms20M -Xmx20M	設置堆大小爲20M
-Xmn10M	設置新生代的內存空間大小爲10M
-XX:+PrintGCDetails	打印GC中的變化
-XX:SurvivorRatio=8	新生代中Eden區域與Survivor區域的大小比值
-XX:+UseSerialGC	在新生代和老年代中使用串行收集器，因爲-verbose:gc參數對Parallel Scavenge收集器不起做用，沒法顯示顯示GC的操做內容，所以採用串行收集器

• 示例代碼說明
• 該段代碼一共建立了4個數組對象，在給allocation4分配空間前的內存空間使用狀況以下： eden區爲8M 兩個Survivor爲各佔1M，年老代佔10M。

 

• 須要執行一次MinorGC才能給allocation4分配空間（Eden區滿時），分配成功之後內存空間使用狀況以下：

2. GC日誌

• [GC [DefNew ... ...]

• GC日誌開頭的信息經過設置-verbose:gc參數後才能輸出。

• "[GC"和"[Full GC"說明此次垃圾收集的停頓類型，若是此次GC發生了Stop-The-World，則爲"[Full GC"，不然爲"[GC"

• "[DefNew "表示GC發生的區域爲Serial收集器的新生代中，DefNew是"Default New Generation"的縮寫。Serial收集器的老年代和永久代分別表示爲"Tenured"、"Perm"

• ** eden space 8192K, 52% used**

• 新生代的Eden區總共大小爲8MB，使用掉的4MB是用來存放allocation4對象

• tenured generation total 10240K, used 6144K

• 老年代大小爲10MB，使用掉的6MB是用來存放allocation一、allocation2和allocation3這3個對象

　　 中間的Survivor區域佔用了19%的內存 此處筆者不是很明白，若是有知道的網友能夠給我留言，幫助講解一下，謝謝！

3、內存分配的原則

對象優先分配在Eden區上

虛擬機參數爲「-verbose:gc -XX:+PrintGCDetails -Xms20M -Xmx20M -Xmn10M -XX:SurvivorRatio=8」，即10M新生代，10M老年代，10M新生代中8M的Eden區，兩個Survivor區各1M。代碼都是同一段

public class EdenAllocationTest
{
    private static final int _1MB = 1024 * 1024;
    
    public static void main(String[] args)
    {
        byte[] allocation1 = new byte[2 * _1MB];
        byte[] allocation2 = new byte[2 * _1MB];
        byte[] allocation3 = new byte[2 * _1MB];
        byte[] allocation4 = new byte[4 * _1MB];
    }
}

Client模式下

[GC [DefNew: 6487K->194K(9216K), 0.0042856 secs] 6487K->6338K(19456K), 0.0043281 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 def new generation   total 9216K, used 4454K [0x0000000005180000, 0x0000000005b80000, 0x0000000005b80000)
  eden space 8192K,  52% used [0x0000000005180000, 0x00000000055a9018, 0x0000000005980000)
  from space 1024K,  18% used [0x0000000005a80000, 0x0000000005ab0810, 0x0000000005b80000)
  to   space 1024K,   0% used [0x0000000005980000, 0x0000000005980000, 0x0000000005a80000)
 tenured generation   total 10240K, used 6144K [0x0000000005b80000, 0x0000000006580000, 0x0000000006580000)
   the space 10240K,  60% used [0x0000000005b80000, 0x0000000006180048, 0x0000000006180200, 0x0000000006580000)
 compacting perm gen  total 21248K, used 2982K [0x0000000006580000, 0x0000000007a40000, 0x000000000b980000)
   the space 21248K,  14% used [0x0000000006580000, 0x0000000006869890, 0x0000000006869a00, 0x0000000007a40000)
No shared spaces configured.

Server模式下

Heap
 PSYoungGen      total 9216K, used 6651K [0x000000000af20000, 0x000000000b920000, 0x000000000b920000)
  eden space 8192K, 81% used [0x000000000af20000,0x000000000b59ef70,0x000000000b720000)
  from space 1024K, 0% used [0x000000000b820000,0x000000000b820000,0x000000000b920000)
  to   space 1024K, 0% used [0x000000000b720000,0x000000000b720000,0x000000000b820000)
 PSOldGen        total 10240K, used 4096K [0x000000000a520000, 0x000000000af20000, 0x000000000af20000)
  object space 10240K, 40% used [0x000000000a520000,0x000000000a920018,0x000000000af20000)
 PSPermGen       total 21248K, used 2972K [0x0000000005120000, 0x00000000065e0000, 0x000000000a520000)
  object space 21248K, 13% used [0x0000000005120000,0x0000000005407388,0x00000000065e0000)

看到在Client模式下，最後分配的4M在新生代中，先分配的6M在老年代中；

在Server模式下，最後分配的4M在老年代中，先分配的6M在新生代中。說明不一樣的垃圾收集器組合對於對象的分配是有影響的。

講下二者差異的緣由：

 

一、Client模式下，新生代分配了6M，虛擬機在GC前有6487K，比6M也就是6144K多，多主要是由於TLAB和EdenAllocationTest這個對象佔的空間，TLAB能夠經過「-XX:+PrintTLAB」這個虛擬機參數來查看大小。

OK，6M多了，而後來了一個4M的，Eden+一個Survivor總共就9M不夠分配了【感受這個地方說的有點不對，由於觸發一次Minor GC的狀況是是Eden內存滿，這裏不該該把Survivor算進去】，這時候就會觸發一次Minor GC。可是觸發Minor GC也沒用，由於allocation一、allocation二、allocation3三個引用還存在，另外一塊1M的Survivor也不夠放下這6M，那麼此次Minor GC的效果實際上是經過分配擔保機制將這6M的內容轉入老年代中。而後再來一個4M的，此時Minor GC以後新生代只剩下了194K了，夠分配了，因此4M順利進入新生代。

 

二、Server模式下，前面都同樣，可是在GC的時候有一點區別。在GC前還會進行一次判斷，若是要分配的內存>=Eden區大小的一半，那麼會直接把要分配的內存放入老年代中。要分配4M，Eden區8M，恰好一半，並且老年代10M，夠分配，因此4M就直接進入老年代去了。爲了驗證一下結論，咱們把3個2M以後分配的4M改成3M看一下。

 

public class EdenAllocationTest
{
    private static final int _1MB = 1024 * 1024;
    
    public static void main(String[] args)
    {
        byte[] allocation1 = new byte[2 * _1MB];
        byte[] allocation2 = new byte[2 * _1MB];
        byte[] allocation3 = new byte[2 * _1MB];
        byte[] allocation4 = new byte[3 * _1MB];
    }
}

運行結果爲

[GC [PSYoungGen: 6487K->352K(9216K)] 6487K->6496K(19456K), 0.0035661 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC [PSYoungGen: 352K->0K(9216K)] [PSOldGen: 6144K->6338K(10240K)] 6496K->6338K(19456K) [PSPermGen: 2941K->2941K(21248K)], 0.0035258 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
Heap
 PSYoungGen      total 9216K, used 3236K [0x000000000af40000, 0x000000000b940000, 0x000000000b940000)
  eden space 8192K, 39% used [0x000000000af40000,0x000000000b269018,0x000000000b740000)
  from space 1024K, 0% used [0x000000000b740000,0x000000000b740000,0x000000000b840000)
  to   space 1024K, 0% used [0x000000000b840000,0x000000000b840000,0x000000000b940000)
 PSOldGen        total 10240K, used 6338K [0x000000000a540000, 0x000000000af40000, 0x000000000af40000)
  object space 10240K, 61% used [0x000000000a540000,0x000000000ab70858,0x000000000af40000)
 PSPermGen       total 21248K, used 2982K [0x0000000005140000, 0x0000000006600000, 0x000000000a540000)
  object space 21248K, 14% used [0x0000000005140000,0x0000000005429890,0x0000000006600000)

看到3M在新生代中，6M經過分配擔保機制進入老年代了。

 

大對象直接進入老年代

虛擬機參數爲「-XX:+PrintGCDetails -Xms20M -Xmx20M -Xmn10M -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=3145728」，最後那個參數表示大於這個設置值的對象直接在老年代中分配，這樣作的目的是爲了不在Eden區和兩個Survivor區之間發生大量的內存複製。測試代碼爲

public class OldTest
{
    private static final int _1MB = 1024 * 1024;
    
    public static void main(String[] args)
    {
         byte[] allocation = new byte[4 * _1MB];
    }
}

Client模式下

Heap
 def new generation   total 9216K, used 507K [0x0000000005140000, 0x0000000005b40000, 0x0000000005b40000)
  eden space 8192K,   6% used [0x0000000005140000, 0x00000000051bef28, 0x0000000005940000)
  from space 1024K,   0% used [0x0000000005940000, 0x0000000005940000, 0x0000000005a40000)
  to   space 1024K,   0% used [0x0000000005a40000, 0x0000000005a40000, 0x0000000005b40000)
 tenured generation   total 10240K, used 4096K [0x0000000005b40000, 0x0000000006540000, 0x0000000006540000)
   the space 10240K,  40% used [0x0000000005b40000, 0x0000000005f40018, 0x0000000005f40200, 0x0000000006540000)
 compacting perm gen  total 21248K, used 2972K [0x0000000006540000, 0x0000000007a00000, 0x000000000b940000)
   the space 21248K,  13% used [0x0000000006540000, 0x00000000068272a0, 0x0000000006827400, 0x0000000007a00000)
No shared spaces configured.

Server模式下

Heap
 PSYoungGen      total 9216K, used 4603K [0x000000000afc0000, 0x000000000b9c0000, 0x000000000b9c0000)
  eden space 8192K, 56% used [0x000000000afc0000,0x000000000b43ef40,0x000000000b7c0000)
  from space 1024K, 0% used [0x000000000b8c0000,0x000000000b8c0000,0x000000000b9c0000)
  to   space 1024K, 0% used [0x000000000b7c0000,0x000000000b7c0000,0x000000000b8c0000)
 PSOldGen        total 10240K, used 0K [0x000000000a5c0000, 0x000000000afc0000, 0x000000000afc0000)
  object space 10240K, 0% used [0x000000000a5c0000,0x000000000a5c0000,0x000000000afc0000)
 PSPermGen       total 21248K, used 2972K [0x00000000051c0000, 0x0000000006680000, 0x000000000a5c0000)
  object space 21248K, 13% used [0x00000000051c0000,0x00000000054a72a0,0x0000000006680000)

看到Client模式下4M直接進入了老年代，Server模式下4M還在新生代中。產生這個差異的緣由是「-XX:PretenureSizeThreshold」這個參數對Serial+Serial Old垃圾收集器組合有效而對Parallel+Serial Old垃圾收集器組合無效。

 

其餘幾條原則

上面列舉的原則其實不重要，只是演示罷了，也不須要記住，由於實際過程當中咱們可能使用的並非上面的垃圾收集器的組合，可能使用ParNew垃圾收集器，可能使用G1垃圾收集器。場景不少，重要的是要在實際使用的時候有辦法知道使用的垃圾收集器對於對象分配有哪些原則，由於理解這些原則纔是調優的第一步。下面列舉一下對象分配的另外兩條原則：

一、長期存活的對象將進入老年代。Eden區中的對象在一次Minor GC後沒有被回收，則對象年齡+1，當對象年齡達到「-XX:MaxTenuringThreshold」設置的值的時候，對象就會被晉升到老年代中

二、Survivor空間中相同年齡的全部對象大小總和大於Survivor空間的一半，年齡大於或等於該年齡的對象就能夠直接進入老年代，無須等到「-XX:MaxTenuringThreshold」設置要求的年齡