文章目錄

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

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

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

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

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

G1的日志參數分為等級遞增的三塊，這篇文章將會分別介紹每一部分參數的作用和調優時候使用的場景。

一、如何在idea打印G1日志

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

二、G1基礎參數

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

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

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

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

三、G1新生代收集

和其他垃圾收集器一樣，G1也使用-XX:PrintGCDetails打印出詳細的垃圾收集日志，下面是新生代收集的標準流程，我在這里將它分成了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、 四個關鍵信息

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

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

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

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

• Code Root Fixup ：釋放用于管理并行垃圾收集活動的數據結構，應該接近于0，該步驟是線性執行的；
• Code Root Purge：清理更多的數據結構，應該很快，耗時接近于0，也是線性執行。
• Clear CT：清理card table

4、包含一些擴展功能

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

5、展示了不同代的大小變化，以及堆大小的自適應調整。

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

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

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

四、并發垃圾收集

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

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、標志著并發垃圾收集階段的開始

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

2、表示第并發標記階段做的第一個事情：根分區掃描

• GC concurrent-root-region-scan-start：根分區掃描開始，根分區掃描主要掃描的是新的survivor分區，找到這些分區內的對象指向當前分區的引用，如果發現有引用，則做個記錄；
• GC concurrent-root-region-scan-end：根分區掃描結束，耗時0.0460160 secs

3、表示并發標記階段

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

4、重新標記階段，會Stop the World

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

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

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

6、并發清理階段

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

五、程序發生Full GC

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

• Full GC的原因，這個圖里是Allocation Failure，還有一個常見的原因是Metadata GC Threshold；
• Full GC發生的頻率，每隔幾天發生一次Full GC還可以接受，但是每隔1小時發生一次Full GC則不可接受；
• Full GC的耗時，這張圖里的Full GC耗時3s（PS：按照我的經驗，實際運行中如果發生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]

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

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 、記錄了應用線程在安全點被暫停的總時間（也就是STW的總時間）
2、 記錄了在兩個安全點之間應用線程運行的時間

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

---

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

總結

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

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。