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

什么時(shí)候會(huì)發(fā)生垃圾收集

首先我們來(lái)看一個(gè)問(wèn)題，那就是什么時(shí)候會(huì)發(fā)生垃圾回收？

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

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

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

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

怎么拿到GC日志

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

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

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

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

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

-XX:+PrintCommandLineFlags

進(jìn)行打?。?/p>

PS+PO日志分析

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

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

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

第三行打印的是當(dāng)前Java服務(wù)啟動(dòng)后鎖配置的參數(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ù)等一些信息。

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

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

//第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、最前面一個(gè)時(shí)間2020-08-23T15:35:30.747+0800代表的是垃圾回收發(fā)生的時(shí)間。

• 2、緊接著下面的一個(gè)數(shù)字：5.486表示的是從Java虛擬機(jī)啟動(dòng)以來(lái)經(jīng)過(guò)的秒數(shù)。

• 3、再往下一個(gè)GC (Allocation Failure)表示發(fā)生GC的原因，這里是表示分配空間失敗而發(fā)生了GC。

• 4、PSYoungGen，PS表示的是Parallel Scavenge收集器，YoungGen表示的是當(dāng)前發(fā)生GC的地方是年輕代，注意，這里不同收集器會(huì)有不同的名字，如ParNew收集器就會(huì)顯示為ParNew等。

• 5、中括號(hào)之內(nèi)的一個(gè)數(shù)字32768K->3799K(37888K)這個(gè)表示的是：GC前當(dāng)前內(nèi)存區(qū)域使用空間->GC后當(dāng)前內(nèi)存區(qū)域使用的內(nèi)存空間(當(dāng)前區(qū)域的總內(nèi)存空間)。從這里可以看到，一次GC之后，大部分空間都被回收掉了。

• 6、中括號(hào)之外的數(shù)字32768K->3807K(123904K)這個(gè)表示的是：GC前Java堆已使用容量->GC后Java堆已使用容量(Java堆使用的總?cè)萘?
  這里需要注意的是5和6中的這兩組數(shù)字相減得到的值一般是不相等的，這是因?yàn)榭偪臻g下面還包括了老年代發(fā)生回收后釋放的空間大小，可能有人會(huì)覺(jué)得奇怪，這里明明只有新生代發(fā)生了GC，為什么老年代會(huì)有空間釋放？
  不知道大家還記不記得我在前兩篇文章中提到了，S區(qū)如果空間不夠的話會(huì)利用擔(dān)保機(jī)制向老年代借用空間，所以借來(lái)的空間時(shí)可能被釋放的。

• 7、0.1129986 secs這個(gè)表示的是GC所花費(fèi)時(shí)間，secs表示單位是秒。

• 8、[Times: user=0.02 sys=0.00, real=0.11 secs] 這一部分并不是所有的垃圾收集器都會(huì)打印，user=0.02表示用戶態(tài)消耗的CPU時(shí)間，sys=0.00表示內(nèi)核態(tài)消耗的CPU時(shí)間和操作從開(kāi)始到結(jié)束所經(jīng)過(guò)的墻鐘時(shí)間。

• 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三個(gè)區(qū)域的回收信息，而且第9行對(duì)比非常明顯，新生代全部回收掉了，老年代回收了一小部分，而方法區(qū)一點(diǎn)都沒(méi)有回收掉，這也體現(xiàn)了三個(gè)區(qū)域內(nèi)所存對(duì)象的區(qū)別。

墻鐘時(shí)間和cpu時(shí)間

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

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

CMS日志分析

我們垃圾收集器切換為CMS

-XX:+UseConcMarkSweepGC

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

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

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

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兩個(gè)收集器都啟用了。打開(kāi)第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日志，我們把一個(gè)完成的老年代回收日志復(fù)制出來(lái)：

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對(duì)應(yīng)的是CMS工作機(jī)制的第一步初始標(biāo)記，主要是尋找GCRoot對(duì)象

• 2、中括號(hào)內(nèi)10443K(86016K)表示的是當(dāng)前區(qū)域已經(jīng)使用大小和總空間大小

• 3、中括號(hào)外13477K(124736K)表示的是堆內(nèi)已使用空間大小和堆內(nèi)總空間大小

• 4、CMS-concurrent-mark-start這里對(duì)應(yīng)了CMS工作機(jī)制中的第二步并發(fā)標(biāo)記。這個(gè)階段主要是根據(jù)GCRoot對(duì)象遍歷整個(gè)引用鏈

• 5、再往后面一行CMS-concurrent-mark: 0.052/0.052 secs，這里的兩個(gè)時(shí)間，第一個(gè)表示該階段持續(xù)的cpu時(shí)間和墻鐘時(shí)間

• 6、后面的CMS-concurrent-preclean和CMS-concurrent-abortable-preclean對(duì)應(yīng)了預(yù)清理和可中斷預(yù)清理階段

• 7、CMS-concurrent-sweep-start對(duì)應(yīng)最終標(biāo)記，此階段需要STW，可以看到，在此階段前發(fā)生了一次Young GC,這是為了減少STW時(shí)間。

• 8、CMS-concurrent-sweep并發(fā)清除垃圾，CMS-concurrent-reset重置線程

G1日志分析

切換到G1垃圾收集器：

-XX:+UseG1GC?

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

可以看到，這個(gè)文件相比較于其他垃圾收集器要復(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ù)制出來(lái)：

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)的時(shí)間。

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

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

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

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

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

利用工具分析GC日志

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

• 1、吞吐量(Throughput)
  吞吐量=運(yùn)行用戶代碼時(shí)間/(運(yùn)行用戶代碼時(shí)間+GC時(shí)間)

• 2、GC暫停時(shí)間(Pause Time)
  Stop The World時(shí)間

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

gceasy

• 1、打開(kāi)官網(wǎng)地址：https://gceasy.io/

• 2、上傳gc日志
  
  然后可以進(jìn)入主頁(yè)面：
  
  這里已經(jīng)幫我們把吞吐量和GC暫停時(shí)間統(tǒng)計(jì)出來(lái)了，當(dāng)然還有其他指標(biāo)也有統(tǒng)計(jì)，有了工具我們就可以對(duì)比指標(biāo)來(lái)確認(rèn)哪種收集器適合自己的系統(tǒng)了。

GCViewer

• 1、下載gcviewer的jar包

• 2、執(zhí)行命令java -jar gcviewer-1.36-SNAPSHOT.jar
  
  打開(kāi)主界面：
  
  點(diǎn)擊File–>Open File
  
  在右邊的第一個(gè)Summary概要里面可以看到吞吐量的統(tǒng)計(jì)。

  切換到第三個(gè)標(biāo)簽Pause：
  
  可以查看到各種停頓時(shí)間的統(tǒng)計(jì)。

總結(jié)

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

感謝閱讀