【譯】深入理解G1的GC日志（一）

本文翻譯自：https://www.redhat.com/en/blog/collecting-and-reading-g1-garbage-collector-logs-part-2?source=author&term=22991

這篇文章將深入研究G1的日志和調優參數。為了在實際工作中對G1進行調優，作為開發者的你需要理解G1垃圾收集器的每個步驟，以及每個步驟在整個垃圾收集周期中的作用。為了方便讀者學習，這篇文章將G1的日志參數分為等級遞增的三塊，這篇文章將會分別介紹每一部分參數的作用和調優時候使用的場景。

1. 基礎參數 - 在生產中使用G1收集器，必須使用這些參數
2. 高級參數 - 隨著應用的成熟或業務負載的增加，需要使用這些參數針對某些問題進行調優。
3. Debug參數 - 這些參數是用來解決特定的性能問題，如果某個問題在非生產環境中無法復現，才會在生產環境中使用這些參數排查問題。

基礎參數

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

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

新生代收集

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

1. 四個關鍵信息
   • 新生代垃圾收集發生的時間——2016-12-12T10:40:18.811-0500，通過設置-XX:+PrintGCDateStamps參數可以打印出這個時間；
   • JVM啟動后的相對時間——25.959
   • 這次收集的類型——新生代收集，只回收Eden分區
   • 這次收集花費的時間——0.0305171s，即30ms
2. 列出了新生代收集中并行收集的詳細過程
   • Parallel Time：并行收集任務在運行過程中引發的STW（Stop The World）時間，從新生代垃圾收集開始到最后一個任務結束，共花費26.6ms
   • 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:1097.0M(1097.0M)->0.0B(967.0M)：（1）當前新生代收集觸發的原因是Eden空間滿了，分配了1097M，使用了1097M；（2）所有的Eden分區都被疏散處理了，在新生代結束后Eden分區的使用大小成為了0.0B；（3）Eden分區的大小縮小為967.0M
   • Survivors:13.0M->139.0M：由于年輕代分區的回收處理，survivor的空間從13.0M漲到139.0M；
   • Heap:1694.4M(2048.0M)->736.3M(2048.0M)：（1）在本次垃圾收集活動開始的時候，堆空間整體使用量是1694.4M，堆空間的最大值是2048M；（2）在本次垃圾收集結束后，堆空間的使用量是763.4M，最大值保持不變。
6. 第6點展示了本次新生代垃圾收集的時間
   • user=0.8：垃圾收集線程在新生代垃圾收集過程中消耗的CPU時間，這個時間跟垃圾收集線程的個數有關，可能會比real time大很多；
   • sys=0.0：內核態線程消耗的CPU時間
     -real=0.03：本次垃圾收集真正消耗的時間；

并發垃圾收集

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

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.0030613s
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.3055438s
4. 重新標記階段，會Stop the World
   • Finalize Marking：Finalizer列表里的Finalizer對象處理，耗時0.0014099s；
   • GC ref-proc：引用（soft、weak、final、phantom、JNI等等）處理，耗時0.0000480s；
   • Unloading：類卸載，耗時0.0025840s；
   • 除了前面這幾個事情，這個階段最關鍵的結果是：繪制出當前并發周期中整個堆的最后面貌，剩余的SATB緩沖區會在這里被處理，所有存活的對象都會被標記；

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

   • 計算出最后存活的對象：標記出initial-mark階段后分配的對象；標記出至少有一個存活對象的分區；
   • 為下一個并發標記階段做準備，previous和next位圖會被清理；
   • 沒有存活對象的老年代分區和巨型對象分區會被釋放和清理；
   • 處理沒有任何存活對象的分區的RSet；
   • 所有的老年代分區會按照自己的存活率（存活對象占整個分區大小的比例）進行排序，為后面的CSet選擇過程做準備；
6. 并發清理階段
   • GC concurrent-cleanup-start：并發清理階段啟動。完成第5步剩余的清理工作；將完全清理好的分區加入到二級free列表，等待最終還會到總體的free列表；
   • GC concurrent-cleanup-end：并發清理階段結束，耗時0.0012954s

混合收集

在并發收集階段結束后，你會看到混合收集階段的日志，如下圖所示，該日志的大部分跟之前討論的新生代收集相同，只有第1部分不一樣：GC pause(G1 Evacuation Pause)(mixed),0.0129474s，這一行表示這是一個混合垃圾收集周期；在混合垃圾收集處理的CSet不僅包括新生代的分區，還包括老年代分區——也就是并發標記階段標記出來的那些老年代分區。

Full GC

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

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

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

1. 記錄了應用線程在安全點被暫停的總時間（也就是STW的總時間）
2. 記錄了讓所有應用線程進入安全點所花費的總時間
3. 記錄了在兩個安全點之間應用線程運行的時間

總結

這篇文章只是翻譯了原文的第一部分，基礎參數篇，我接下來會有一篇或兩篇文章完成原文的高級參數和Debug參數兩部分。------

本號專注于后端技術、JVM問題排查和優化、Java面試題、個人成長和自我管理等主題，為讀者提供一線開發者的工作和成長經驗，期待你能在這里有所收獲。