GC日誌檢視分析
0. 前言
GC(Garbage Collection)是Java虛擬機器中一個很重要的組成部分,在很多情況下我們都需要檢視它的日誌,下面內容就是介紹如何檢視GC日誌。
1. GET GC日誌
1.1 輸出日誌引數
要檢視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 日誌檔案的輸出路徑
在這裡我使用PrintGCDetails這個引數。
1.2 編寫演示類
接下來我先編寫一個演示類,程式碼如下
package edu.jyu.jvm;
/**
* GC日誌演示
* @author Jason
*
*/
public class GCLogDemo {
public static void main(String[] args) {
int _1m = 1024 * 1024;
byte [] data = new byte[_1m];
// 將data置為null即讓它成為垃圾
data = null;
// 通知垃圾回收器回收垃圾
System.gc();
}
}
1.3 執行
好了,現在要執行這個演示類,不過在執行的時候要加上虛擬機器引數PrintGCDetails,下面我分別在Eclipse和命令列中執行這個程式。
1.3.1 在Eclipse執行
先要設定一下Run Configurations
設定如下
然後點Run執行,執行後就輸出了下面結果,這些就是GC日誌。
[GC (System.gc()) [PSYoungGen: 3686 K->664K(38400K)] 3686K->672K(125952K), 0.0016607 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC (System.gc()) [PSYoungGen: 664K->0K(38400K)] [ParOldGen: 8K->537K(87552K)] 672K->537K(125952K), [Metaspace: 2754K->2754K(1056768K)], 0.0059024 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
Heap
PSYoungGen total 38400K, used 333K [0x00000000d5c00000, 0x00000000d8680000, 0x0000000100000000)
eden space 33280K, 1% used [0x00000000d5c00000,0x00000000d5c534a8,0x00000000d7c80000)
from space 5120K, 0% used [0x00000000d7c80000,0x00000000d7c80000,0x00000000d8180000)
to space 5120K, 0% used [0x00000000d8180000,0x00000000d8180000,0x00000000d8680000)
ParOldGen total 87552K, used 537K [0x0000000081400000, 0x0000000086980000, 0x00000000d5c00000)
object space 87552K, 0% used [0x0000000081400000,0x00000000814864a0,0x0000000086980000)
Metaspace used 2761K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 299K, capacity 386K, committed 512K, reserved 1048576K
1.3.2 在命令列執行
因為Eclipse已經把類編譯好了,所以我直接進入工程目錄下執行。
輸出結果
[GC (System.gc()) [PSYoungGen: 3702K->784K(38400K)] 3702K->792K(125952K), 0.0014644 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC (System.gc()) [PSYoungGen: 784K->0K(38400K)] [ParOldGen: 8K->648K(87552K)] 792K->648K(125952K), [Metaspace: 2763K->2763K(1056768K)], 0.0057136 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
Heap
PSYoungGen total 38400K, used 333K [0x00000000d5c00000, 0x00000000d8680000, 0x0000000100000000)
eden space 33280K, 1% used [0x00000000d5c00000,0x00000000d5c534a8,0x00000000d7c80000)
from space 5120K, 0% used [0x00000000d7c80000,0x00000000d7c80000,0x00000000d8180000)
to space 5120K, 0% used [0x00000000d8180000,0x00000000d8180000,0x00000000d8680000)
ParOldGen total 87552K, used 648K [0x0000000081400000, 0x0000000086980000, 0x00000000d5c00000)
object space 87552K, 0% used [0x0000000081400000,0x00000000814a2318,0x0000000086980000)
Metaspace used 2770K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 300K, capacity 386K, committed 512K, reserved 1048576K
2. 分析日誌
好了,GC日誌已經得到,現在就是分析了,我把Eclipse執行後輸出的GC日誌放到這裡來分析
[GC (System.gc()) [PSYoungGen: 3686K->664K(38400K)] 3686K->672K(125952K), 0.0016607 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC (System.gc()) [PSYoungGen: 664K->0K(38400K)] [ParOldGen: 8K->537K(87552K)] 672K->537K(125952K), [Metaspace: 2754K->2754K(1056768K)], 0.0059024 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
Heap
PSYoungGen total 38400K, used 333K [0x00000000d5c00000, 0x00000000d8680000, 0x0000000100000000)
eden space 33280K, 1% used [0x00000000d5c00000,0x00000000d5c534a8,0x00000000d7c80000)
from space 5120K, 0% used [0x00000000d7c80000,0x00000000d7c80000,0x00000000d8180000)
to space 5120K, 0% used [0x00000000d8180000,0x00000000d8180000,0x00000000d8680000)
ParOldGen total 87552K, used 537K [0x0000000081400000, 0x0000000086980000, 0x00000000d5c00000)
object space 87552K, 0% used [0x0000000081400000,0x00000000814864a0,0x0000000086980000)
Metaspace used 2761K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 299K, capacity 386K, committed 512K, reserved 1048576K
GC日誌開頭的”[GC”和”[Full GC”說明了這次垃圾收集的停頓型別,如果有”Full”,說明這次GC發生了”Stop-The-World”。因為是呼叫了System.gc()方法觸發的收集,所以會顯示”[Full GC (System.gc())”,不然是沒有後面的(System.gc())的。
“[PSYoungGen”和”[ParOldGen”是指GC發生的區域,分別代表使用Parallel Scavenge垃圾收集器的新生代和使用Parallel old垃圾收集器的老生代。為什麼是這兩個垃圾收集器組合呢?因為我的jvm開啟的模式是Server,而Server模式的預設垃圾收集器組合便是這個,在命令列輸入java -version就可以看到自己的jvm預設開啟模式。還有一種是client模式,預設組合是Serial收集器和Serial Old收集器組合。
在方括號中”PSYoungGen:”後面的”3686K->664K(38400K)”代表的是”GC前該記憶體區域已使用的容量->GC後該記憶體區域已使用的容量(該記憶體區域總容量)”
在方括號之外的”3686K->672K(125952K)”代表的是”GC前Java堆已使用容量->GC後Java堆已使用容量(Java堆總容量)”
再往後的”0.0016607 sec”代表該記憶體區域GC所佔用的時間,單位是秒。
再後面的”[Times: user=0.00 sys=0.00, real=0.00 secs]”,user代表程序在使用者態消耗的CPU時間,sys代表代表程序在核心態消耗的CPU時間、real代表程式從開始到結束所用的時鐘時間。這個時間包括其他程序使用的時間片和程序阻塞的時間(比如等待 I/O 完成)。
至於後面的”eden”代表的是Eden空間,還有”from”和”to”代表的是Survivor空間。
如果上面的內容有錯誤的地方或者講的不好的地方,還請大家指點一下,我好及時修改。