eclipse設定檢視GC日誌和如何理解GC日誌

eclipse的gc日誌配置可以在eclipse.ini中加入引數實現,不過列印的日誌是整個eclipse的記憶體回收情況，如何實現

準確的看一個java應用的gc日誌呢.

1. Run as -> Run configurations -> java應用名 -> arguments ->VM arguments，加入jvm引數就行

2. 測試程式碼

package cn.erong.test;

public class Jtest {
	private static final int _1M = 1024*1024;
	public static void main(String[] args) {
		byte[] allocation1,allocation2,allocation3,allocation4;
		allocation1 = new byte[_1M/4];
		allocation2 = new byte[_1M/4];
		allocation3 = new byte[4*_1M];
		allocation4 = new byte[4*_1M];
		allocation4 = null;
		allocation4 = new byte[4*_1M];
		
	}
}	

3.  測試看下，在vm arguments 中加入

-Xms20m --jvm堆的最小值
-Xmx20m --jvm堆的最大值
-XX:+PrintGCTimeStamps -- 列印出GC的時間資訊
-XX:+PrintGCDetails  --列印出GC的詳細資訊
-verbose:gc --開啟gc日誌
-Xloggc:d:/gc.log -- gc日誌的存放位置
-Xmn10M -- 新生代記憶體區域的大小
-XX:SurvivorRatio=8 --新生代記憶體區域中Eden和Survivor的比例

4 . run  看下日誌，到d盤找到 gc.log，如下

Java HotSpot(TM) Client VM (25.151-b12) for windows-x86 JRE (1.8.0_151-b12), built on Sep  5 2017 19:31:49 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 3567372k(982296k free), swap 7133056k(3042564k free)
CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:NewSize=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:-UseLargePagesIndividualAllocation 
0.091: [GC (Allocation Failure) 0.091: [DefNew: 5427K->995K(9216K), 0.0036445 secs] 5427K->5091K(19456K), 0.0038098 secs] [Times: user=0.00 sys=0.02, real=0.00 secs] 
0.095: [GC (Allocation Failure) 0.095: [DefNew: 5091K->0K(9216K), 0.0012412 secs] 9187K->5090K(19456K), 0.0012908 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 def new generation   total 9216K, used 4260K [0x04000000, 0x04a00000, 0x04a00000)
  eden space 8192K,  52% used [0x04000000, 0x044290e8, 0x04800000)
  from space 1024K,   0% used [0x04800000, 0x04800000, 0x04900000)
  to   space 1024K,   0% used [0x04900000, 0x04900000, 0x04a00000)
 tenured generation   total 10240K, used 5090K [0x04a00000, 0x05400000, 0x05400000)
   the space 10240K,  49% used [0x04a00000, 0x04ef8ac0, 0x04ef8c00, 0x05400000)
 Metaspace       used 84K, capacity 2242K, committed 2368K, reserved 4480K

理解GC日誌

217.539: [GC (Allocation Failure) 217.539: [DefNew: 102646K->10770K(102976K), 0.0415902 secs] 239776K->153169K(331528K), 0.0416785 secs] [Times: user=0.03 sys=0.02, real=0.04 secs] 
221.383: [Full GC (System.gc()) 221.383: [Tenured: 142398K->92063K(228552K), 0.3029342 secs] 193477K->92063K(331528K), [Metaspace: 65120K->65120K(68992K)], 0.3031417 secs] [Times: user=0.30 sys=0.00, real=0.30 secs] 
281.396: [Full GC (System.gc()) 281.396: [Tenured: 92063K->93342K(228552K), 0.2394086 secs] 129487K->93342K(331528K), [Metaspace: 65137K->65137K(68992K)], 0.2395739 secs] [Times: user=0.23 sys=0.00, real=0.24 secs] 

1. 最前面的數字217.539:代表GC發生的時間，從虛擬機器啟動開始算起

2. GC日誌開頭的[GC和FULL GC]說明這次垃圾收集的停頓型別，而不是區分新生代和老年代的。

FULL GC : 說明這次GC是發生了執行緒停頓Stop-The-World,如果是System.gc()方法所觸發的收集，，那麼在這裡將顯示[Full GC (System)

3. [DefNew,[Tenured,[Perm表示GC發生的區域，這裡顯示的區域名稱和使用的垃圾收集器是密切相關的

1>在Serial收集器中新生代名為Default New Generation ，顯示就是DefNew

2>垃圾收集器ParNew中新生代名稱就會變為[Parnew,意思為Parallel New Generation 

3>如果採用Parrallel Scavenge收集器，那麼它配套的新生代名稱為PSYongGen

老年代和永久代同理，名稱由垃圾收集器決定

4.[DefNew: 102646K->10770K(102976K), 0.0415902 secs] 239776K->153169K(331528K), 0.0416785 secs] [Times: user=0.03 sys=0.02, real=0.04 secs] 就這段而言，

1>方括號內部102646K->10770K(102976K)的含義是GC前改記憶體區域已使用記憶體->GC後改記憶體區域使用容量(該記憶體區域總容量)

2>方括號外 239776K->153169K(331528K)表示GC前java堆已使用容量->GC後java堆已使用容量(java堆總容量)

3>在往後時間表示該記憶體區域gc清理用的時間

4>[Times: user=0.03 sys=0.02, real=0.04 secs]

這裡面的user、sys和real與linux的time命令所輸出的時間含義一致，分別表示使用者態消耗的CPU時間、核心態消耗的CPU事件和操作從開始到結束經歷的牆鍾時間

牆鍾時間和CPU時間的區別是，牆鍾時間包括各種非運算的等待耗時(i/o,執行緒阻塞)，而CPU時間不包括這些，但是如果是多核，

多執行緒會疊加這些CPU時間，此時user或sys時間超過real時間完全是正常的

-------------------------------------------------------------------------------------------------------------

部落格內容來自書籍和網際網路，加上自己的一些總結