不同的垃圾收集器產(chǎn)生的GC日志大致遵循了同一個規(guī)則，只是有些許不同，不過對于G1收集器的GC日志和其他垃圾收集器有較大差別，話不多說，正式進(jìn)入正文。。。

什么時候會發(fā)生垃圾收集

首先我們來看一個問題，那就是什么時候會發(fā)生垃圾回收？

在Java中，GC是由JVM自動完成的，根據(jù)JVM系統(tǒng)環(huán)境而定，所以時機(jī)是不確定的。當(dāng)然，我們可以手動進(jìn)行垃圾回收，比如調(diào)用System.gc()方法通知JVM進(jìn)行一次垃圾回收，但是具體什么時刻運(yùn)行也無法控制。也就是說System.gc()只是通知要回收，什么時候回收由JVM決定。

一般以下幾種情況會發(fā)生垃圾回收：

當(dāng)Eden區(qū)或者S區(qū)不夠用時
老年代空間不夠用了時
方法區(qū)空間不夠用時
System.gc() 時

注意：可能有些人會以為方法區(qū)是不會發(fā)生垃圾回收的，其實(shí)方法區(qū)也是會發(fā)生垃圾回收的，只不過大部分情況下，方法區(qū)發(fā)生垃圾回收之后效率不是很高，大部分內(nèi)存都回收不掉，所以我們一般討論垃圾回收的時候也只討論堆內(nèi)的回收

怎么拿到GC日志

發(fā)生GC之后，我們要分析GC日志，當(dāng)然就首先要拿到GC日志，上一篇講述JVM參數(shù)分類及常用參數(shù)分析時有提到，打印GC日志可以通過如下命令：

-XX:+PrintGCDetails?-XX:+PrintGCTimeStamps?-XX:+PrintGCDateStamps?-Xloggc:D:\\gc.log

配置上之后啟動服務(wù)：

找到gc.log文件，注意，剛開始如果一次GC都沒發(fā)生日志是空的，可以等到發(fā)生GC之后再打開：

從日志上可以看出來，jdk1.8中默認(rèn)使用的是Parallel Scavenge+Parallel Old收集器，當(dāng)然我們也可以通過參數(shù)：

-XX:+PrintCommandLineFlags

進(jìn)行打印：

PS+PO日志分析

前面三行應(yīng)該都能看懂：

第一行打印的是當(dāng)前所使用的的HotSpot虛擬機(jī)及其對應(yīng)版本號；

第二行打印的是操作系統(tǒng)相關(guān)的內(nèi)存信息；

第三行打印的是當(dāng)前Java服務(wù)啟動后鎖配置的參數(shù)信息：

CommandLine?flags:?-XX:-BytecodeVerificationLocal?-XX:-BytecodeVerificationRemote?-XX:InitialHeapSize=131854336?-XX:+ManagementServer?-XX:MaxHeapSize=2109669376?-XX:+PrintGC?-XX:+PrintGCDateStamps?-XX:+PrintGCDetails?-XX:+PrintGCTimeStamps?-XX:TieredStopAtLevel=1?-XX:+UseCompressedClassPointers?-XX:+UseCompressedOops?-XX:-UseLargePagesIndividualAllocation?-XX:+UseParallelGC?

包括了堆空間打印，以及使用的垃圾收集器及我們自己配置的打印GC日志相關(guān)參數(shù)等一些信息。

搜索公眾號?Java筆記蝦，回復(fù)“后端面試”，送你一份面試題大全.pdf

下面第4行開始才是我們的GC日志，我們把第4行還有第9行復(fù)制出來分析一下：

//第4行
2020-08-23T15:35:30.747+0800:?5.486:?[GC?(Allocation?Failure)?[PSYoungGen:?32768K->3799K(37888K)]?32768K->3807K(123904K),?0.1129986?secs]?[Times:?user=0.02?sys=0.00,?real=0.11?secs]?
//第9行
2020-08-23T15:35:34.635+0800:?9.374:?[Full?GC?(Metadata?GC?Threshold)?[PSYoungGen:?5092K->0K(136192K)]?[ParOldGen:?12221K->12686K(63488K)]?17314K->12686K(199680K),?[Metaspace:?20660K->20660K(1067008K)],?0.0890985?secs]?[Times:?user=0.25?sys=0.00,?real=0.09?secs]?

1、最前面一個時間2020-08-23T15:35:30.747+0800代表的是垃圾回收發(fā)生的時間。
2、緊接著下面的一個數(shù)字：5.486表示的是從Java虛擬機(jī)啟動以來經(jīng)過的秒數(shù)。
3、再往下一個GC (Allocation Failure)表示發(fā)生GC的原因，這里是表示分配空間失敗而發(fā)生了GC。
4、PSYoungGen，PS表示的是Parallel Scavenge收集器，YoungGen表示的是當(dāng)前發(fā)生GC的地方是年輕代，注意，這里不同收集器會有不同的名字，如ParNew收集器就會顯示為ParNew等。
5、中括號之內(nèi)的一個數(shù)字32768K->3799K(37888K)這個表示的是：GC前當(dāng)前內(nèi)存區(qū)域使用空間->GC后當(dāng)前內(nèi)存區(qū)域使用的內(nèi)存空間(當(dāng)前區(qū)域的總內(nèi)存空間)。從這里可以看到，一次GC之后，大部分空間都被回收掉了。
6、中括號之外的數(shù)字32768K->3807K(123904K)這個表示的是：GC前Java堆已使用容量->GC后Java堆已使用容量(Java堆使用的總?cè)萘?
這里需要注意的是5和6中的這兩組數(shù)字相減得到的值一般是不相等的，這是因?yàn)榭偪臻g下面還包括了老年代發(fā)生回收后釋放的空間大小，可能有人會覺得奇怪，這里明明只有新生代發(fā)生了GC，為什么老年代會有空間釋放？
不知道大家還記不記得我在前兩篇文章中提到了，S區(qū)如果空間不夠的話會利用擔(dān)保機(jī)制向老年代借用空間，所以借來的空間時可能被釋放的。
7、0.1129986 secs這個表示的是GC所花費(fèi)時間，secs表示單位是秒。
8、[Times: user=0.02 sys=0.00, real=0.11 secs] 這一部分并不是所有的垃圾收集器都會打印，user=0.02表示用戶態(tài)消耗的CPU時間，sys=0.00表示內(nèi)核態(tài)消耗的CPU時間和操作從開始到結(jié)束所經(jīng)過的墻鐘時間。
9、最后再看看其他行ParOldGen表示Parallel Old收集器在回收老年代，Metaspace表示的是方法區(qū)(jdk1.7是永久代)
10、我們看到第9行Full GC表示發(fā)生了Full GC，F(xiàn)ullGC=Minor GC+Major GC+Metaspace GC，所以后面可以看到PSYoungGen，ParOldGen，Metaspace三個區(qū)域的回收信息，而且第9行對比非常明顯，新生代全部回收掉了，老年代回收了一小部分，而方法區(qū)一點(diǎn)都沒有回收掉，這也體現(xiàn)了三個區(qū)域內(nèi)所存對象的區(qū)別。

墻鐘時間和cpu時間

墻鐘時間(Wall Clock Time)包括各種非運(yùn)算的等待耗時，例如等待磁盤I/O、等待線程阻塞，而CPU時間不包括這些不需要消耗CPU的時間。

搜索公眾號?Java筆記蝦，回復(fù)“后端面試”，送你一份面試題大全.pdf

CMS日志分析

我們垃圾收集器切換為CMS

-XX:+UseConcMarkSweepGC

注意，CMS也是一款老年代收集器，使用這個參數(shù)后新生代默認(rèn)會使用ParNew收集器

然后重啟服務(wù)，等候垃圾回收之后，打開gc.log文件。

前面兩行和上面一樣，我們把第三行復(fù)制出來看看垃圾收集器是否切換成功：

CommandLine?flags:?-XX:-BytecodeVerificationLocal?-XX:-BytecodeVerificationRemote?-XX:InitialHeapSize=131854336?-XX:+ManagementServer?-XX:MaxHeapSize=2109669376?-XX:MaxNewSize=348966912?-XX:MaxTenuringThreshold=6?-XX:OldPLABSize=16?-XX:+PrintGC?-XX:+PrintGCDateStamps?-XX:+PrintGCDetails?-XX:+PrintGCTimeStamps?-XX:TieredStopAtLevel=1?-XX:+UseCompressedClassPointers?-XX:+UseCompressedOops?-XX:+UseConcMarkSweepGC?-XX:-UseLargePagesIndividualAllocation?-XX:+UseParNewGC?

可以看到，CMS和ParNew兩個收集器都啟用了。打開第4行日志：

2020-08-23T17:00:34.728+0800:?5.259:?[GC?(Allocation?Failure)?2020-08-23T17:00:34.728+0800:?5.259:?[ParNew:?34432K->3862K(38720K),?0.0185214?secs]?34432K->3862K(124736K),?0.0188547?secs]?[Times:?user=0.02?sys=0.00,?real=0.02?secs]?

這里的回收信息和上面一樣，也就是新生代名字不一樣，這里叫ParNew。我們主要看看老年代CMS的GC日志，我們把一個完成的老年代回收日志復(fù)制出來：

2020-08-23T17:00:47.650+0800:?18.182:?[GC?(CMS?Initial?Mark)?[1?CMS-initial-mark:?30298K(86016K)]?34587K(124736K),?0.0014342?secs]?[Times:?user=0.00?sys=0.00,?real=0.00?secs]?
2020-08-23T17:00:47.651+0800:?18.183:?[CMS-concurrent-mark-start]
2020-08-23T17:00:47.712+0800:?18.244:?[CMS-concurrent-mark:?0.061/0.061?secs]?[Times:?user=0.13?sys=0.00,?real=0.06?secs]?
2020-08-23T17:00:47.712+0800:?18.244:?[CMS-concurrent-preclean-start]
2020-08-23T17:00:47.714+0800:?18.245:?[CMS-concurrent-preclean:?0.001/0.001?secs]?[Times:?user=0.00?sys=0.00,?real=0.00?secs]?
2020-08-23T17:00:47.714+0800:?18.246:?[CMS-concurrent-abortable-preclean-start]
2020-08-23T17:00:48.143+0800:?18.674:?[GC?(Allocation?Failure)?2020-08-23T17:00:48.143+0800:?18.674:?[ParNew:?38720K->4111K(38720K),?0.0101415?secs]?69018K->38573K(124736K),?0.0102502?secs]?[Times:?user=0.06?sys=0.00,?real=0.01?secs]?
2020-08-23T17:00:48.451+0800:?18.983:?[CMS-concurrent-abortable-preclean:?0.274/0.737?secs]?[Times:?user=0.94?sys=0.13,?real=0.74?secs]?
2020-08-23T17:00:48.451+0800:?18.983:?[GC?(CMS?Final?Remark)?[YG?occupancy:?23345?K?(38720?K)]2020-08-23T17:00:48.451+0800:?18.983:?[Rescan?(parallel)?,?0.0046112?secs]2020-08-23T17:00:48.456+0800:?18.987:?[weak?refs?processing,?0.0006259?secs]2020-08-23T17:00:48.457+0800:?18.988:?[class?unloading,?0.0062187?secs]2020-08-23T17:00:48.463+0800:?18.994:?[scrub?symbol?table,?0.0092387?secs]2020-08-23T17:00:48.472+0800:?19.004:?[scrub?string?table,?0.0006408?secs][1?CMS-remark:?34461K(86016K)]?57806K(124736K),?0.0219024?secs]?[Times:?user=0.05?sys=0.01,?real=0.02?secs]?
2020-08-23T17:00:48.473+0800:?19.005:?[CMS-concurrent-sweep-start]
2020-08-23T17:00:48.489+0800:?19.020:?[CMS-concurrent-sweep:?0.015/0.015?secs]?[Times:?user=0.01?sys=0.00,?real=0.02?secs]?
2020-08-23T17:00:48.489+0800:?19.020:?[CMS-concurrent-reset-start]
2020-08-23T17:00:48.492+0800:?19.023:?[CMS-concurrent-reset:?0.003/0.003?secs]?[Times:?user=0.00?sys=0.00,?real=0.00?secs]?

如果不了解CMS垃圾收集器工作機(jī)制的，可以參考：

https://blog.csdn.net/zwx900102/article/details/108180739

1、CMS Initial Mark對應(yīng)的是CMS工作機(jī)制的第一步初始標(biāo)記，主要是尋找GCRoot對象
2、中括號內(nèi)10443K(86016K)表示的是當(dāng)前區(qū)域已經(jīng)使用大小和總空間大小
3、中括號外13477K(124736K)表示的是堆內(nèi)已使用空間大小和堆內(nèi)總空間大小
4、CMS-concurrent-mark-start這里對應(yīng)了CMS工作機(jī)制中的第二步并發(fā)標(biāo)記。這個階段主要是根據(jù)GCRoot對象遍歷整個引用鏈
5、再往后面一行CMS-concurrent-mark: 0.052/0.052 secs，這里的兩個時間，第一個表示該階段持續(xù)的cpu時間和墻鐘時間
6、后面的CMS-concurrent-preclean和CMS-concurrent-abortable-preclean對應(yīng)了預(yù)清理和可中斷預(yù)清理階段
7、CMS-concurrent-sweep-start對應(yīng)最終標(biāo)記，此階段需要STW，可以看到，在此階段前發(fā)生了一次Young GC,這是為了減少STW時間。
8、CMS-concurrent-sweep并發(fā)清除垃圾，CMS-concurrent-reset重置線程

G1日志分析

切換到G1垃圾收集器：

-XX:+UseG1GC?

然后重啟服務(wù)，等待發(fā)生垃圾回收之后打開gc.log文件：

可以看到，這個文件相比較于其他垃圾收集器要復(fù)雜的多。我們還是先看下第3行，確認(rèn)是否使用了G1收集器：

CommandLine?flags:?-XX:-BytecodeVerificationLocal?-XX:-BytecodeVerificationRemote?-XX:InitialHeapSize=131854336?-XX:+ManagementServer?-XX:MaxHeapSize=2109669376?-XX:+PrintGC?-XX:+PrintGCDateStamps?-XX:+PrintGCDetails?-XX:+PrintGCTimeStamps?-XX:TieredStopAtLevel=1?-XX:+UseCompressedClassPointers?-XX:+UseCompressedOops?-XX:+UseG1GC?-XX:-UseLargePagesIndividualAllocation?

可以看到確實(shí)使用了G1收集器。我們找到一次完整的G1日志，復(fù)制出來：

2020-08-23T18:44:39.787+0800:?2.808:?[GC?pause?(G1?Evacuation?Pause)?(young),?0.0029103?secs]
???[Parallel?Time:?1.9?ms,?GC?Workers:?4]
??????[GC?Worker?Start?(ms):?Min:?2807.7,?Avg:?2807.8,?Max:?2807.8,?Diff:?0.1]
??????[Ext?Root?Scanning?(ms):?Min:?0.3,?Avg:?0.6,?Max:?0.8,?Diff:?0.5,?Sum:?2.2]
??????[Update?RS?(ms):?Min:?0.0,?Avg:?0.0,?Max:?0.0,?Diff:?0.0,?Sum:?0.0]
?????????[Processed?Buffers:?Min:?0,?Avg:?0.0,?Max:?0,?Diff:?0,?Sum:?0]
??????[Scan?RS?(ms):?Min:?0.0,?Avg:?0.0,?Max:?0.0,?Diff:?0.0,?Sum:?0.0]
??????[Code?Root?Scanning?(ms):?Min:?0.0,?Avg:?0.0,?Max:?0.0,?Diff:?0.0,?Sum:?0.0]
??????[Object?Copy?(ms):?Min:?0.9,?Avg:?1.2,?Max:?1.4,?Diff:?0.5,?Sum:?4.6]
??????[Termination?(ms):?Min:?0.0,?Avg:?0.0,?Max:?0.0,?Diff:?0.0,?Sum:?0.0]
?????????[Termination?Attempts:?Min:?1,?Avg:?2.5,?Max:?4,?Diff:?3,?Sum:?10]
??????[GC?Worker?Other?(ms):?Min:?0.0,?Avg:?0.0,?Max:?0.0,?Diff:?0.0,?Sum:?0.2]
??????[GC?Worker?Total?(ms):?Min:?1.7,?Avg:?1.8,?Max:?1.8,?Diff:?0.1,?Sum:?7.1]
??????[GC?Worker?End?(ms):?Min:?2809.5,?Avg:?2809.5,?Max:?2809.5,?Diff:?0.0]
???[Code?Root?Fixup:?0.0?ms]
???[Code?Root?Purge:?0.0?ms]
???[Clear?CT:?0.1?ms]
???[Other:?1.0?ms]
??????[Choose?CSet:?0.0?ms]
??????[Ref?Proc:?0.8?ms]
??????[Ref?Enq:?0.0?ms]
??????[Redirty?Cards:?0.1?ms]
??????[Humongous?Register:?0.0?ms]
??????[Humongous?Reclaim:?0.0?ms]
??????[Free?CSet:?0.0?ms]
???[Eden:?6144.0K(6144.0K)->0.0B(12.0M)?Survivors:?0.0B->1024.0K?Heap:?6144.0K(126.0M)->1520.0K(126.0M)]
?[Times:?user=0.00?sys=0.00,?real=0.00?secs]?

[GC pause (G1 Evacuation Pause) (young), 0.0029103 secs]這里表示發(fā)生GC的區(qū)域是Young區(qū)，后面就是總共耗費(fèi)的時間。

注意：G1雖然在物理上取消了區(qū)域的劃分，但是邏輯上依然保留了，所以日志中還是會顯示young，F(xiàn)ull GC會用mixed來表示。

[Parallel Time: 1.9 ms, GC Workers: 4] 這句表示線程的并行時間和并行的線程數(shù)

[GC Worker Start (ms): Min: 2807.7, Avg: 2807.8, Max: 2807.8, Diff: 0.1]這個表示并行的每個線程的開始時間最小值，平均值和最大值以及時間差(Max-Min)。

后面就是一些具體的執(zhí)行步驟，在這里就不逐行去說明了，如果有興趣的可以看看文檔。這里面有非常詳細(xì)的解釋，不過是英文版本，但是大致應(yīng)該能看得懂：

https://blogs.oracle.com/poonam/understanding-g1-gc-logs

利用工具分析GC日志

雖然說我們從日志上能看懂GC日志，但是如果需要進(jìn)行調(diào)優(yōu)，我們最關(guān)注的是2個點(diǎn)：

1、吞吐量(Throughput)
吞吐量=運(yùn)行用戶代碼時間/(運(yùn)行用戶代碼時間+GC時間)
2、GC暫停時間(Pause Time)
Stop The World時間

那么我們直接從GC日志上很難看出來這兩個指標(biāo)，如果要靠自己計算去確認(rèn)問題，我覺得這會是一個噩夢。所以同樣的，我們需要有工具來幫助我們分析，下面就介紹2款常用的工具。

gceasy

1、打開官網(wǎng)地址：https://gceasy.io/
2、上傳gc日志

然后可以進(jìn)入主頁面：

這里已經(jīng)幫我們把吞吐量和GC暫停時間統(tǒng)計出來了，當(dāng)然還有其他指標(biāo)也有統(tǒng)計，有了工具我們就可以對比指標(biāo)來確認(rèn)哪種收集器適合自己的系統(tǒng)了。

GCViewer

1、下載gcviewer的jar包
2、執(zhí)行命令java -jar gcviewer-1.36-SNAPSHOT.jar

打開主界面：

點(diǎn)擊File–>Open File

在右邊的第一個Summary概要里面可以看到吞吐量的統(tǒng)計。
切換到第三個標(biāo)簽Pause：

可以查看到各種停頓時間的統(tǒng)計。

總結(jié)

本文主要介紹了常用的垃圾收集器的GC日志應(yīng)該如何進(jìn)行分析，并且介紹了兩款常用的工具來幫助我們更好更直觀的分析GC日志。

來源：blog.csdn.net/zwx900102/article/details/108274141
版權(quán)申明：內(nèi)容來源網(wǎng)絡(luò)，版權(quán)歸原創(chuàng)者所有。除非無法確認(rèn)，我們都會標(biāo)明作者及出處，如有侵權(quán)煩請告知，我們會立即刪除并表示歉意。謝謝!

感謝閱讀

教你如何通過分析GC日志來進(jìn)行JVM調(diào)優(yōu)