文章目錄

• • • • 一、如何在idea打印G1日志
      • 二、G1基礎(chǔ)參數(shù)
      • 三、G1新生代收集
      • • 1、 四個關(guān)鍵信息
        • 2、 列出了新生代收集中并行收集的詳細過程
        • 3、列出了新生代GC中的一些任務(wù)：
        • 4、包含一些擴展功能
        • 5、展示了不同代的大小變化，以及堆大小的自適應(yīng)調(diào)整。
        • 6、第6點展示了本次新生代垃圾收集的時間
      • 四、并發(fā)垃圾收集
      • • 1、標(biāo)志著并發(fā)垃圾收集階段的開始
        • 2、表示第并發(fā)標(biāo)記階段做的第一個事情：根分區(qū)掃描
        • 3、表示并發(fā)標(biāo)記階段
        • 4、重新標(biāo)記階段，會Stop the World
        • 5、清理階段，也會Stop the World
        • 6、并發(fā)清理階段
      • 五、程序發(fā)生Full GC

寫在前面： 我是「境里婆娑」。我還是從前那個少年，沒有一絲絲改變，時間只不過是考驗，種在心中信念絲毫未減，眼前這個少年，還是最初那張臉，面前再多艱險不退卻。
寫博客的目的就是分享給大家一起學(xué)習(xí)交流，如果您對 Java感興趣，可以關(guān)注我，我們一起學(xué)習(xí)。

提起看GC日志大部分同學(xué)可能都會皺起眉頭不知道如何看、什么時候看以及GC日志如何幫助我們調(diào)優(yōu)JVM等。本篇文章將講解主流垃圾回收器G1，目前Java官方推薦使用G1，所以學(xué)看G1垃圾回收日志迫在眉睫。

在學(xué)習(xí)查看G1 GC日志之前，如果對G1不是很了解，可以看這篇文章，講的非常詳細。

傳送門： G1垃圾收集器簡介

G1的日志參數(shù)分為等級遞增的三塊，這篇文章將會分別介紹每一部分參數(shù)的作用和調(diào)優(yōu)時候使用的場景。

一、如何在idea打印G1日志

在idea中配置啟動參數(shù)
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseG1GC

二、G1基礎(chǔ)參數(shù)

如果你要在生產(chǎn)環(huán)境中使用G1 GC，下面這些跟日志相關(guān)的參數(shù)是必備的，有了這些參數(shù)，你才能排查基本的垃圾回收問題。

-Xloggc：/path/to/gc.log寫入GC日志的路徑

-XX：+UseGCLogFileRotation	啟用GC日志文件輪換
-XX：NumberOfGCLogFiles =	要保留的旋轉(zhuǎn)GC日志文件數(shù)
-XX：GCLogFileSize =	每個GC日志文件的大小以啟動輪換
-XX：+ PrintGCDetial	詳細的GC日志
-XX：+ PrintGCDateStamps	每次GC時會打印程序啟動后至GC發(fā)生的時間戳
-XX：+ PrintGCApplicationStoppedTime	GC期間應(yīng)用程序停止的時間
-XX：+ PrintGCApplicationConcurrentTime	應(yīng)用程序在GC之間運行的時間
-XX：-PrintCommandLineFlags	在GC日志中打印所有命令行標(biāo)志
-XX:MaxGCPauseMillis=n	設(shè)置最大GC停頓時間(GC pause time)指標(biāo)(target). 這是一個軟性指標(biāo)(soft goal), JVM 會盡量去達成這個目標(biāo).
XX:InitiatingHeapOccupancyPercent=n	啟動并發(fā)GC周期時的堆內(nèi)存占用百分比. G1之類的垃圾收集器用它來觸發(fā)并發(fā)GC周期,基于整個堆的使用率,而不只是某一代內(nèi)存的使用比. 值為 0 則表示"一直執(zhí)行GC循環(huán)". 默認(rèn)值為 45.
-XX:NewRatio=n	新生代與老生代(new/old generation)的大小比例(Ratio). 默認(rèn)值為 2.
-XX:SurvivorRatio=n	eden/survivor 空間大小的比例(Ratio). 默認(rèn)值為 8.
-XX:MaxTenuringThreshold=n	提升年老代的最大臨界值(tenuring threshold). 默認(rèn)值為 15.
-XX:G1ReservePercent=n	設(shè)置堆內(nèi)存保留為假天花板的總量,以降低提升失敗的可能性. 默認(rèn)值是 10.
-XX:G1HeapRegionSize=n	使用G1時Java堆會被分為大小統(tǒng)一的的區(qū)(region)。此參數(shù)可以指定每個heap區(qū)的大小. 默認(rèn)值將根據(jù) heap size 算出最優(yōu)解. 最小值為 1Mb, 最大值為 32Mb.

使用-XX:GCLogFileSize設(shè)置合適的GC日志文件大小，使用-XX:NumberOfGCLogFiles設(shè)置要保留的GC日志文件個數(shù)，使用-Xloggc:/path/to/gc.log設(shè)置GC日志文件的位置，通過上面三個參數(shù)保留應(yīng)用在運行過程中的GC日志信息，我建議最少保留一個星期的GC日志，這樣應(yīng)用的運行時信息足夠多的，方便排查問題。

三、G1新生代收集

和其他垃圾收集器一樣，G1也使用-XX:PrintGCDetails打印出詳細的垃圾收集日志，下面是新生代收集的標(biāo)準(zhǔn)流程，我在這里將它分成了6個步驟：

1 2020-04-25T15:36:17.135+0800: [GC pause (G1 Evacuation Pause) (young), 0.0044414 secs]2 [Parallel Time: 3.4 ms, GC Workers: 4][GC Worker Start (ms): Min: 8782.3, Avg: 8783.2, Max: 8785.7, Diff: 3.3][Ext Root Scanning (ms): Min: 0.0, Avg: 0.4, Max: 0.6, Diff: 0.6, Sum: 1.6][Update RS (ms): Min: 0.0, Avg: 1.0, Max: 1.5, Diff: 1.5, Sum: 4.1][Processed Buffers: Min: 0, Avg: 2.5, Max: 6, Diff: 6, Sum: 10][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.0, Avg: 1.0, Max: 1.3, Diff: 1.3, Sum: 3.9][Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2][GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1][GC Worker Total (ms): Min: 0.0, Avg: 2.5, Max: 3.3, Diff: 3.3, Sum: 9.9][GC Worker End (ms): Min: 8785.7, Avg: 8785.7, Max: 8785.7, Diff: 0.0]3 [Code Root Fixup: 0.0 ms][Code Root Migration: 0.0 ms][Clear CT: 0.0 ms]4 [Other: 1.0 ms][Choose CSet: 0.0 ms][Ref Proc: 0.6 ms][Ref Enq: 0.0 ms][Free CSet: 0.0 ms]5 [Eden: 4096.0K(4096.0K)->0.0B(3072.0K) Survivors: 1024.0K->1024.0K Heap: 23.9M(28.0M)->20.4M(28.0M)]6 [Times: user=0.00 sys=0.02, real=0.01 secs]

1、 四個關(guān)鍵信息

• 新生代垃圾收集發(fā)生的時間——2020-04-25T15:36:17.135+0800，通過設(shè)置-XX:+PrintGCDateStamps參數(shù)可以打印出這個時間；
• 這次收集的類型——新生代收集，只回收Eden分區(qū)
• 這次收集花費的時間——0.0044414 secs，即4ms

2、 列出了新生代收集中并行收集的詳細過程

• Parallel Time：并行收集任務(wù)在運行過程中引發(fā)的STW（Stop The World）時間，從新生代垃圾收集開始到最后一個任務(wù)結(jié)束，共花費3.4 ms
• GC Workers：有4個線程負責(zé)垃圾收集，通過參數(shù)-XX:ParallelGCThreads設(shè)置，這個參數(shù)的值的設(shè)置，跟CPU有關(guān)，如果物理CPU支持的線程個數(shù)小于8，則最多設(shè)置為8；如果物理CPU支持的線程個數(shù)大于8，則默認(rèn)值為number * 5/8
• GC Worker Start：第一個垃圾收集線程開始工作時JVM啟動后經(jīng)過的時間（min）；最后一個垃圾收集線程開始工作時JVM啟動后經(jīng)過的時間（max）；diff表示min和max之間的差值。理想情況下，你希望他們幾乎是同時開始，即diff趨近于0。
• Ext Root Scanning：掃描root集合（線程棧、JNI、全局變量、系統(tǒng)表等等）花費的時間，掃描root集合是垃圾收集的起點，嘗試找到是否有root集合中的節(jié)點指向當(dāng)前的收集集合（CSet）
• Update RS(Remembered Set or RSet)：每個分區(qū)都有自己的RSet，用來記錄其他分區(qū)指向當(dāng)前分區(qū)的指針，如果RSet有更新，G1中會有一個post-write barrier管理跨分區(qū)的引用——新的被引用的card會被標(biāo)記為dirty，并放入一個日志緩沖區(qū)，如果這個日志緩沖區(qū)滿了會被加入到一個全局的緩沖區(qū)，在JVM運行的過程中還有線程在并發(fā)處理這個全局日志緩沖區(qū)的dirty card。Update RS表示允許垃圾收集線程處理本次垃圾收集開始前沒有處理好的日志緩沖區(qū)，這可以確保當(dāng)前分區(qū)的RSet是最新的。
• Processed Buffers，這表示在Update RS這個過程中處理多少個日志緩沖區(qū)。
• Scan RS：掃描每個新生代分區(qū)的RSet，找出有多少指向當(dāng)前分區(qū)的引用來自CSet。
• Code Root Scanning：掃描代碼中的root節(jié)點（局部變量）花費的時間
• Object Copy：在疏散暫停期間，所有在CSet中的分區(qū)必須被轉(zhuǎn)移疏散，Object Copy就負責(zé)將當(dāng)前分區(qū)中存活的對象拷貝到新的分區(qū)。
• Termination：當(dāng)一個垃圾收集線程完成任務(wù)時，它就會進入一個臨界區(qū)，并嘗試幫助其他垃圾線程完成任務(wù)（steal outstanding tasks），min表示該垃圾收集線程什么時候嘗試terminatie，max表示該垃圾收集回收線程什么時候真正terminated。
• Termination Attempts：如果一個垃圾收集線程成功盜取了其他線程的任務(wù)，那么它會再次盜取更多的任務(wù)或再次嘗試terminate，每次重新terminate的時候，這個數(shù)值就會增加。
• GC Worker Other：垃圾收集線程在完成其他任務(wù)的時間
• GC Worker Total：展示每個垃圾收集線程的最小、最大、平均、差值和總共時間。
• GC Worker End：min表示最早結(jié)束的垃圾收集線程結(jié)束時該JVM啟動后的時間；max表示最晚結(jié)束的垃圾收集線程結(jié)束時該JVM啟動后的時間。理想情況下，你希望它們快速結(jié)束，并且最好是同一時間結(jié)束。

3、列出了新生代GC中的一些任務(wù)：

• Code Root Fixup ：釋放用于管理并行垃圾收集活動的數(shù)據(jù)結(jié)構(gòu)，應(yīng)該接近于0，該步驟是線性執(zhí)行的；
• Code Root Purge：清理更多的數(shù)據(jù)結(jié)構(gòu)，應(yīng)該很快，耗時接近于0，也是線性執(zhí)行。
• Clear CT：清理card table

4、包含一些擴展功能

• Choose CSet：選擇要進行回收的分區(qū)放入CSet（G1選擇的標(biāo)準(zhǔn)是垃圾最多的分區(qū)優(yōu)先，也就是存活對象率最低的分區(qū)優(yōu)先）
• Ref Proc：處理Java中的各種引用——soft、weak、final、phantom、JNI等等。
• Ref Enq：遍歷所有的引用，將不能回收的放入pending列表
• Redirty Card：在回收過程中被修改的card將會被重置為dirty
• Humongous Register：JDK8u60提供了一個特性，巨型對象可以在新生代收集的時候被回收——通過G1ReclaimDeadHumongousObjectsAtYoungGC設(shè)置，默認(rèn)為true。
• Humongous Reclaim：做下列任務(wù)的時間：確保巨型對象可以被回收、釋放該巨型對象所占的分區(qū)，重置分區(qū)類型，并將分區(qū)還到free列表，并且更新空閑空間大小。
• Free CSet：將要釋放的分區(qū)還回到free列表。

5、展示了不同代的大小變化，以及堆大小的自適應(yīng)調(diào)整。

Eden:4096.0K(4096.0K)->0.0B(3072.0K)：（1）當(dāng)前新生代收集觸發(fā)的原因是Eden空間滿了，分配了4096K，使用了4096K；（2）所有的Eden分區(qū)都被疏散處理了，在新生代結(jié)束后Eden分區(qū)的使用大小成為了0.0B；（3）Eden分區(qū)的大小縮小為3072K
Survivors:1024.0K->1024.0K：由于年輕代分區(qū)的無回收處理，survivor的空間不變。
Heap: 23.9M(28.0M)->20.4M(28.0M）：（1）在本次垃圾收集活動開始的時候，堆空間整體使用量是23.9M，堆空間的最大值是28.0M；（2）在本次垃圾收集結(jié)束后，堆空間的使用量是20.4M，最大值保持不變。

6、第6點展示了本次新生代垃圾收集的時間

• user=0.8：垃圾收集線程在新生代垃圾收集過程中消耗的CPU時間，這個時間跟垃圾收集線程的個數(shù)有關(guān)，可能會比real time大很多；
• sys=0.0：內(nèi)核態(tài)線程消耗的CPU時間
• real=0.03：本次垃圾收集真正消耗的時間；

四、并發(fā)垃圾收集

G1的第二種收集活動是并發(fā)垃圾收集，并發(fā)垃圾收集的觸發(fā)條件有很多，但是做的工作都相同，它的日志所示：

1 2020-04-25T15:36:17.590+0800: [GC pause (G1 Evacuation Pause) (young),(initial-mark), 0.0043944 secs] 2 2020-04-25T15:36:17.590+0800: [GC concurrent-root-region-scan-start]2020-04-25T15:36:17.594+0800: [GC concurrent-root-region-scan-end, 0.0043944 secs] 3 2020-04-25T15:36:17.594+0800: [GC concurrent-mark-start]2020-04-25T15:36:17.640+0800: [GC concurrent-mark-end, 0.0460160 secs] 4 2020-04-25T15:36:17.640+0800: [GC remark [GC ref-proc, 0.0028598 secs], 0.0130111 secs][Times: user=0.00 sys=0.00, real=0.01 secs] 5 2020-04-25T15:36:17.654+0800: [GC cleanup 18M->18M(56M), 0.0001847 secs][Times: user=0.00 sys=0.00, real=0.00 secs] 6 2020-04-25T15:36:17.890+0800: [GC concurent-cleanup-stat]2020-04-25T15:36:17.904+0800: [GC concurrent-cleanup-end, 0.0001847 secs]

1、標(biāo)志著并發(fā)垃圾收集階段的開始

• GC pause(G1 Evacuation Pause)(young)(initial-mark)：為了充分利用STW的機會來trace所有可達（存活）的對象，initial-mark階段是作為新生代垃圾收集中的一部分存在的（搭便車）。initial-mark設(shè)置了兩個TAMS（top-at-mark-start）變量，用來區(qū)分存活的對象和在并發(fā)標(biāo)記階段新分配的對象。在TAMS之前的所有對象，在當(dāng)前周期內(nèi)都會被視作存活的。

2、表示第并發(fā)標(biāo)記階段做的第一個事情：根分區(qū)掃描

• GC concurrent-root-region-scan-start：根分區(qū)掃描開始，根分區(qū)掃描主要掃描的是新的survivor分區(qū)，找到這些分區(qū)內(nèi)的對象指向當(dāng)前分區(qū)的引用，如果發(fā)現(xiàn)有引用，則做個記錄；
• GC concurrent-root-region-scan-end：根分區(qū)掃描結(jié)束，耗時0.0460160 secs

3、表示并發(fā)標(biāo)記階段

• GC Concurrent-mark-start：并發(fā)標(biāo)記階段開始。（1）并發(fā)標(biāo)記階段的線程是跟應(yīng)用線程一起運行的，不會STW，所以稱為并發(fā)；并發(fā)標(biāo)記階段的垃圾收集線程，默認(rèn)值是Parallel Thread個數(shù)的25%，這個值也可以用參數(shù)-XX:ConcGCThreads設(shè)置；（2）trace整個堆，并使用位圖標(biāo)記所有存活的對象，因為在top TAMS之前的對象是隱式存活的，所以這里只需要標(biāo)記出那些在top TAMS之后、閾值之前的；（3）記錄在并發(fā)標(biāo)記階段的變更，G1這里使用了SATB算法，該算法要求在垃圾收集開始的時候給堆做一個快照，在垃圾收集過程中這個快照是不變的，但實際上肯定有些對象的引用會發(fā)生變化，這時候G1使用了pre-write barrier記錄這種變更，并將這個記錄存放在一個SATB緩沖區(qū)中，如果該緩沖區(qū)滿了就會將它加入到一個全局的緩沖區(qū)，同時G1有一個線程在并行得處理這個全局緩沖區(qū)；（4）在并發(fā)標(biāo)記過程中，會記錄每個分區(qū)的存活對象占整個分區(qū)的大小的比率；
• GC Concurrent-mark-end：并發(fā)標(biāo)記階段結(jié)束，耗0.0460160 secs

4、重新標(biāo)記階段，會Stop the World

• Finalize Marking：Finalizer列表里的Finalizer對象處理，耗時0.0130111s；
• GC ref-proc：引用（soft、weak、final、phantom、JNI等等）處理，耗時 0.0028598s；
  除了前面這幾個事情，這個階段最關(guān)鍵的結(jié)果是：繪制出當(dāng)前并發(fā)周期中整個堆的最后面貌，剩余的SATB緩沖區(qū)會在這里被處理，所有存活的對象都會被標(biāo)記；

5、清理階段，也會Stop the World

• 計算出最后存活的對象：標(biāo)記出initial-mark階段后分配的對象；標(biāo)記出至少有一個存活對象的分區(qū)；
• 為下一個并發(fā)標(biāo)記階段做準(zhǔn)備，previous和next位圖會被清理；
• 沒有存活對象的老年代分區(qū)和巨型對象分區(qū)會被釋放和清理；
• 處理沒有任何存活對象的分區(qū)的RSet；
• 所有的老年代分區(qū)會按照自己的存活率（存活對象占整個分區(qū)大小的比例）進行排序，為后面的CSet選擇過程做準(zhǔn)備；

6、并發(fā)清理階段

• GC concurrent-cleanup-start：并發(fā)清理階段啟動。完成第5步剩余的清理工作；將完全清理好的分區(qū)加入到二級free列表，等待最終還會到總體的free列表；
• GC concurrent-cleanup-end：并發(fā)清理階段結(jié)束，耗時0.0001847s

五、程序發(fā)生Full GC

如果堆內(nèi)存空間不足以分配新的對象，或者是Metasapce空間使用率達到了設(shè)定的閾值，那么就會觸發(fā)Full GC——你在使用G1的時候應(yīng)該盡量避免這種情況發(fā)生，因為G1的Full Gc是單線程、會Stop The World，代價非常高。Full GC的日志如下所示，從中你可以看出三類信息

• Full GC的原因，這個圖里是Allocation Failure，還有一個常見的原因是Metadata GC Threshold；
• Full GC發(fā)生的頻率，每隔幾天發(fā)生一次Full GC還可以接受，但是每隔1小時發(fā)生一次Full GC則不可接受；
• Full GC的耗時，這張圖里的Full GC耗時3s（PS：按照我的經(jīng)驗，實際運行中如果發(fā)生Full GC，耗時會比這個多很多）

2020-04-25T18:00:11.267+0800: [Full GC (Allocation Failure) 1520M->918M(1886M), 5.1284574 secs][Eden: 0.0B(93.0M)->0.0B(94.0M) Survivors: 1024.0K->0.0B Heap: 1520.8M(1886.0M)->918.5M(1886.0M)], [Metaspace: 39714K->39714K(1085440K)][Times: user=5.02 sys=0.00, real=5.13 secs] 2020-04-25T18:00:16.395+0800: [Full GC (Allocation Failure) 918M->916M(1886M), 4.7699272 secs][Eden: 0.0B(94.0M)->0.0B(94.0M) Survivors: 0.0B->0.0B Heap: 918.5M(1886.0M)->916.1M(1886.0M)], [Metaspace: 39714K->39488K(1085440K)][Times: user=4.73 sys=0.00, real=4.77 secs]

基礎(chǔ)配置參數(shù)中，我這里還想介紹兩個：-XX:+PrintGCApplicationStoppedTime和-XX:+PrintGCApplicationConcurrentTime，這兩個參數(shù)也可以為你提供有用的信息，如下所示

1 2020-04-25T18:00:11.266+0800: Total time for which application threads were stopped: 0.0024315 seconds 2 2020-04-25T18:00:11.266+0800: Application time: 0.0000549 seconds

1 、記錄了應(yīng)用線程在安全點被暫停的總時間（也就是STW的總時間）
2、 記錄了在兩個安全點之間應(yīng)用線程運行的時間

本篇文章參考：Collecting and reading G1 garbage collector logs

---

由于本人水平有限，難免有不足，懇請各位大佬不吝賜教！

總結(jié)

以上是生活随笔為你收集整理的万字长文教你看懂java G1垃圾回收日志的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。