java中的gc log解讀

標籤：

gc log是java程式在出現記憶體問題時候最好的查看問題的有利日誌。下面我們來一步一步分析gc log。

首先，預設java程式是不會開啟gc log，我們可以在給jvm參數加上-XX:+PrintGCDetails （這個只是我們在本地調試使用，在產生環境下不可使用。

下面我們可以類比一個程式，來查看日誌。

public class GcLog {static final int MB = 1024 * 1024;static void printGC() {byte[] b1, b2, b3, b4;b1 = new byte[MB];b2 = new byte[MB];b3 = new byte[MB];b4 = new byte[2*MB];}public static void main(String[] args) {// TODO Auto-generated method stubprintGC();}}

可以給可以jvm加上如下的啟動參數:-Xmx10M -Xms10M -Xmn6M -XX:+PrintGCDetails -XX:SurvivorRatio=7

從代碼，可以看到jvm分配的記憶體大小一共為10M,其中老變態4M，年輕態6M，同時針對年輕態eden和Survivor共用6M，分配的比例為7:1:1，其中eden大小為4.6M，Survivor的兩個地區各自為0.6M

這裡我們預設採用CMS記憶體回收,下面我們運行程式，會看到如下的日誌

[GC [DefNew: 3298K->149K(5504K), 0.0053498 secs] 3298K->3221K(9600K), 0.0053750 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] Heap def new generation   total 5504K, used 2391K [0x33e60000, 0x34460000, 0x34460000)  eden space 4864K,  46% used [0x33e60000, 0x34090b28, 0x34320000)  from space 640K,  23% used [0x343c0000, 0x343e5418, 0x34460000)  to   space 640K,   0% used [0x34320000, 0x34320000, 0x343c0000) tenured generation   total 4096K, used 3072K [0x34460000, 0x34860000, 0x34860000)   the space 4096K,  75% used [0x34460000, 0x34760030, 0x34760200, 0x34860000) compacting perm gen  total 12288K, used 376K [0x34860000, 0x35460000, 0x38860000)   the space 12288K,   3% used [0x34860000, 0x348be298, 0x348be400, 0x35460000)    ro space 10240K,  55% used [0x38860000, 0x38de3320, 0x38de3400, 0x39260000)    rw space 12288K,  55% used [0x39260000, 0x39906128, 0x39906200, 0x39e60000)

下面來從程式的角度分析日誌的。

程式中按照順序申請了1M-->1M--->1M--->2M的記憶體

當第一次申請1M的時候，新生態空間足夠直接放入

當第二次申請1M的時候，新生態空間依然足夠，直接放入

當第三次申請1M的時候，新生態空間依然足夠，直接放入

當第四次申請1M的時候，新生態空間不足開始GC，而此時有3個1M的對象，而Survivor地區不滿1M，所以直接進入老年態，這是原來的3個1M對象進入老年態，2M的對象進入eden

[GC [DefNew: 3298K->149K(5504K), 0.0053498 secs] 3298K->3221K(9600K), 0.0053750 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

看一下這行：

DefNew表示新生態:3298K->149K(5504K), 0.0053498 secs

表示新生態由3298K回收變成了149K，即之前的3M回收了，5504K表示該地區的總記憶體大小

3298K->3221K(9600K), 0.0053750 secs] 表示整個jvm堆的大小由於沒有可以回收的對象，所以總大小本質沒發生改變，9600K是java的總堆大小9600K。(雖然分配10M，其中還有持久態等其他記憶體地區)

[Times: user=0.00 sys=0.00, real=0.01 secs] 表示gc所花費的系統資源

-------------------------------------------------------------------------------華麗分割線---------------------------------------------------------------------------------------------------------

再來看看這堆詳細的資訊

Heap
 def new generation   total 5504K, used 2391K [0x33e60000, 0x34460000, 0x34460000)------------->新生態的大小，total，used
  eden space 4864K,  46% used [0x33e60000, 0x34090b28, 0x34320000)
  from space 640K,  23% used [0x343c0000, 0x343e5418, 0x34460000)------------->本例中由於該地區很小，無法放入對象，所以其實沒使用到。
  to   space 640K,   0% used [0x34320000, 0x34320000, 0x343c0000)
 tenured generation   total 4096K, used 3072K [0x34460000, 0x34860000, 0x34860000)------------->老年態
   the space 4096K,  75% used [0x34460000, 0x34760030, 0x34760200, 0x34860000)
 compacting perm gen  total 12288K, used 376K [0x34860000, 0x35460000, 0x38860000)------------->由於老年態共4M，已經放入3M了，所以開啟了壓縮。
   the space 12288K,   3% used [0x34860000, 0x348be298, 0x348be400, 0x35460000)
    ro space 10240K,  55% used [0x38860000, 0x38de3320, 0x38de3400, 0x39260000)
    rw space 12288K,  55% used [0x39260000, 0x39906128, 0x39906200, 0x39e60000)

對於產生環境下的java程式可以加上來產生gc log，方便出現問題的時候去排查

-verbose:gc -Xloggc:/usr/gclog -XX:+PrintGCDetails XX:+PrintGCTimeStamps

暫時先到這邊，jvm記憶體模型這裡就不多說了，後續我會寫一些jvm最佳化已經線上調試線上系統的工具。

java中的gc log解讀