JVM關於GC的日志分析

通過閱讀GC日志，我們可以了解Java虛擬機內存分配與回收策略。內存分配與垃圾回收的參數列表

• 一XX： +PrintGC 輸出Gc日志。類似： 一verbose：gc
• 一XX： +PrintGCDetails 輸出GC的詳細日志
• 一XX： +PrintGCTimeStamps 輸出GC的時間戳（以基准時間的形式）
• 一XX： +PrintGCDateStamps輸出GC的時間戳（以日期的形式，如2013一05一04T21 ： 53：59.234+0800 ）
• 一XX： +PrintHeapAtGC 在進行GC的前后打印出堆的信息
• 一Xloggc：. . /logs/gc. log日志文件的輸出路徑

+PrintGC

• 打開GC日志：一verbose：gc
• 這個只會顯示總的GC堆的變化， 如下：

[GC （Allocation Failure） 80832K一>19298K（227840K），0.0084018 secs]
[GC （Metadata GC Threshold） 109499K一>21465K （228352K），0.0184066 secs]
[Full GC （Metadata GC Threshold） 21 465K一>16716K （201728K），0.0619261 secs ]

參數解析：

GC、Full GC： GC的類型，GC只在新生代上進行，Full GC包括永生代，新生代， 老年代。
Allocation Failure： GC發生的原因。
80832K一> 19298K：堆在GC前的大小和GC后的大小。 228840k：現在的堆大小。 0.0084018 secs： GC持續的時間。

PrintGCDetails

-打開GC日志： 一verbose：gc一 XX： +PrintGCDetaiis

輸出信息如下：

[GC （Allocation Failure） [ PSYoungGen： 70640K一> 10116K（141312K） ] 80541K一>20017K （227328K），0.0172573 secs] [Times： user=0.03 sys=0.00， real=0.02 secs ]
[GC （Metadata GC Threshold） [PSYoungGen：98859K一>8154K（142336K） ] 108760K一>21261K （228352K），
0.0151573 secs] [Times： user=0.00 sys=0.01， real=0.02 secs]
[Full GC （Metadata GC Threshold） [PSYoungGen： 8154K一>0K（142336K） ] [ParOldGen： 13107K一>16809K（62464K） ] 21261K一>16809K （204800K），[Metaspace： 20599K一>20599K （1067008K） ]，0.0639732 secs]
[Times： user=0.14 sys=0.00， real=0.06 secs]

參數解析：

GC，Full FC：同樣是GC的類型
Allocation Failure： GC原因
PSYoungGen：使用了Parallel Scavenge並行垃圾收集器的新生代GC前后大小的變化
ParOldGen：使用了Parallel Old並行垃圾收集器的老年代Gc前后大小的變化
Metaspace： 元數據區GC前后大小的變化，JDK1.8中引入了 元數據區以替代永久代
xxx secs ： 指Gc花費的時間
Times： user： 指的是垃圾收集器花費的所有CPU時間，sys： 花費在等待系統調用或系統事件的時間， real ：GC從開始到結束的時間，包括其他進程占用時間片的實際時間。

PrintGCTimeStamps

• 打開GC日志： 一verbose：gc 一XX： +PrintGCDetails 一XX：+PrintGCTimeStamps 一 XX： +PrintGCDateStamps
• 輸入信息如下：

2019一09一24T22：15：24.518+0800：3.287： [GC（Allocation Failure） [ PSYoungGen： 1361 62K一>5113K（136192K） ] 141425K一>17632K （222208K） ，0.0248249 secs] [Times： user=0.05sys=0.00， real=0.03 secs ]
2019一09一24T22：15：25.559+0800：4.329： [ GC（Metadata GC Threshold）[PSYoungGen：97578K一>10068K（274944K） ] 110096K一>22658K （360960K），0.0094071 secs]
[Times： user=0. 00sys=0.00， real=0. 01 secs]
2019一09一24T22：15：25.569+0800：4.338： [Full GC （Metadata GC Threshold）[ PSYoungGen：10068K一>0K（274944K） ] [ ParoldGen： 12590K一>13564K （56320K） ] 22658K一>13564K （331264K） ，
[Metaspace： 20590K一>20590K（1067008K）]， 0. 0494875 secs]
[Times： user=0.17 sys=0. 02，real=0.05 secs ]     

說明：帶上了日期和時間

日志補充說明

• "[GC"和"[Full GC"說明了這次垃圾收集的停頓類型，如果有"Full"則說明GC發生了"StopThe World"
• 使用Serial收集器在新生代的名字是De fault New Generation， 因此顯示的是" [DefNew"
• 使用ParNew收集器在新生代的名字會變成" 【ParNew"，意思是"Parallel New Generation"
• 使用Parallel Scavenge收 集器在新生代的名字是" 【PSYoungGen"
• 老年代的收集和新生代道理一樣，名字也是收集器決定的
• 使用G1收集器的話，會顯示為"garbage一 first heap"
• Allocation Failure 表明本次引起GC的原因是因為在年輕代中沒有足夠的空間能夠存儲新的數據了。
• [PSYoungGen： 5986K一>696K（8704K）] 5986K一> 704K （9216K） 中括號內： GC回收前年輕代大小，回收后大小，（ 年輕代總大小） 括號外： GC回收前年輕代和老年代大小，回收后大小，（ 年輕代和老年代總大小）
• user代表用戶態回收耗時，sys 內核態回收耗時， rea實際耗時。由於多核的原因，時間總和可能會超過real時間

堆空間占用情況說明

 Minor GC說明

 Full GC說明

舉例解讀日志中堆空間數據

示例代碼：

/**
 * 在jdk7 和 jdk8中分別執行
 * -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseSerialGC
 */
public class GCLogTest1 {
    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();
    }
}

 

 

 

 

日志分析工具

可以用一些工具去分析這些gc日志。
常用的日志分析.工具有： GCViewer、GCEasy、GCHisto、GCLogViewer 、Hpjmeter、garbagecat等