天天看點

JVM:33 如何檢視JVM的Full GC日志

1. 示例代碼

package com.webcode;

public class Demo4 {
	
	public static void main(String[] args){
		byte[] array1 = new byte[4 * 1024 * 1024];
		array1 = null;
		byte[] array2 = new byte[2 * 1024 * 1024];
		byte[] array3 = new byte[2 * 1024 * 1024];
		byte[] array4 = new byte[2 * 1024 * 1024];
		byte[] array5 = new byte[128 * 1024];
		
		byte[] array6 = new byte[2 * 1024 * 1024];
	}
}
           

2. GC日志

采用如下JVM參數來運作上述程式:

-XX:NewSize=10485760 -XX:MaxNewSize=10485760 -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=15 -XX:PretenureSizeThreshold=3145728 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log

這裡最關鍵的一個參數,是 “-XX:PretenureSizeThreshold=3145728” ,該參數設定大對象門檻值為3MB,也就是超過3MB,就直接進入老年代。

運作之後的GC日志如下:

0.113: [GC (Allocation Failure) 0.113: [ParNew (promotion failed): 7256K->7953K(9216K), 0.0028080 secs]0.116: [CMS: 8194K->6805K(10240K), 0.0035630 secs] 11352K->6805K(19456K), [Metaspace: 2644K->2644K(1056768K)], 0.0068409 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

Heap

 par new generation   total 9216K, used 2130K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)

  eden space 8192K,  26% used [0x00000000fec00000, 0x00000000fee14930, 0x00000000ff400000)

  from space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)

  to   space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)

 concurrent mark-sweep generation total 10240K, used 6805K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)

 Metaspace       used 2651K, capacity 4486K, committed 4864K, reserved 1056768K

  class space    used 286K, capacity 386K, committed 512K, reserved 1048576K

3. 日志分析

首先看如下代碼:

byte[] array1 = new byte[4 * 1024 * 1024];

        array1 = null;

這行代碼直接配置設定了一個4MB的大對象,此時這個對象會直接進入老年代,接着array1不再引用這個對象。

如下圖所示:

JVM:33 如何檢視JVM的Full GC日志

接着看如下代碼:

        byte[] array2 = new byte[2 * 1024 * 1024];

        byte[] array3 = new byte[2 * 1024 * 1024];

        byte[] array4 = new byte[2 * 1024 * 1024];

        byte[] array5 = new byte[128 * 1024];

 連續配置設定了4個數組,其中3個是2MB的數組,1個是128KB的數組,如下圖所示,全部會進入Eden區域中。

JVM:33 如何檢視JVM的Full GC日志

接着會執行如下代碼:byte[] array6 = new byte[2 * 1024 * 1024];。

因為Eden 區已經放不下了,是以此時會觸發一次Young GC。對應的GC日志如下:

ParNew (promotion failed): 7256K->7953K(9216K), 0.0028080 secs

 這行日志顯示,Eden區原來有700多KB的對象,但是回收之後發現一個都回收不掉,因為都被變量引用了。

是以,正常來說一定會直接把這些對象放入到老年代裡去,但是此時老年代已經有一個4MB的數組了,不能再放下3個2MB的數組和1個128KB的數組。

 接着有如下GC日志:

[CMS: 8194K->6805K(10240K), 0.0035630 secs] 11352K->6805K(19456K), [Metaspace: 2644K->2644K(1056768K)], 0.0068409 secs]

上述日志,說明執行了CMS垃圾回收器的Full GC。也就是對老年代進行Old GC,同時一般會跟一次Young GC關聯,并觸發一次中繼資料區(永久代)的GC。

在CMS Full GC之前,就已經觸發過Young GC了,此時可以看到Young GC已經有了,接着就是執行針對老年代的Old GC,如下GC日志:

CMS: 8194K->6805K(10240K), 0.0035630 secs

這裡看到老年代從8MB左右的對象占用,變成了6MB多的對象占用。這個過程是,在Young GC之後,先把2個2MB的數組放入了老年代,如下圖:

JVM:33 如何檢視JVM的Full GC日志

此時要繼續放1個2MB的數組和1個128KB的數組到老年代,一定會放不下,是以就會觸發CMS的Full GC。進而回收掉其中的一個4MB的數組,因為它沒有引用了。

JVM:33 如何檢視JVM的Full GC日志

 接着放入一個2MB的數組和1個128KB的數組,如下圖所示:

JVM:33 如何檢視JVM的Full GC日志

再結合CMS的垃圾回收日志:  CMS: 8194K->6805K(10240K), 0.0035630 secs ,它是從回收前的8MB變成了6MB。

最後在CMS Full GC執行完畢之後,年輕代的對象都進入了老年代,此時最後一行代碼要在年輕代配置設定2MB的數組就可以成功了。

JVM:33 如何檢視JVM的Full GC日志

4.深入解析

(1)4MB的大對象Array1給配置設定記憶體空間時直接進入老年代,此時不會有GC。因為老年代10M可連續的空閑空間;

(2)當年輕代Eden區域配置設定完3個2M和1個128K對象後,當配置設定第四個2M對象時。此時Eden空間不夠導緻配置設定失敗,觸發Minor GC,此時新生代存活的對象6M+128K大于老年代的可用連續空間,但是老年代可用連續空間大于曆代新生代進入老年代對象的平均大小0,是以配置設定擔當成功,不需要觸發Full GC執行Minor GC;

(3)執行Minor GC年輕代6M+128K對象都存活,但是S0隻有1M空間導緻存活對象進入老年代;

(4)年輕代先将活着的兩個2M對象和128K的對象放入老年代,此時老年代8M+128K,當配置設定最後一個2M對象觸發Full GC,因為可用連續空間小于了2M。此時老年代其中4M大對象可回收2個2M對象和1個128K對象不能回收,Full GC回收完4M對象後再将新生代最後活着的2M對象加入到老年代,是以Minor GC時記憶體空間是沒變的。因為對象都活着,Full GC從8M變成6M。

5.總結

上述案例,當年輕代存活的對象太多放不下老年代了,就會觸發CMS的Full  GC。