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

javaadu發表於2019-07-21

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

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

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

基礎引數

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

G1 GC的基礎引數

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

新生代收集

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

G1的新生代垃圾收集

四個關鍵資訊
- 新生代垃圾收集發生的時間——2016-12-12T10:40:18.811-0500，通過設定-XX:+PrintGCDateStamps引數可以列印出這個時間；
- JVM啟動後的相對時間——25.959
- 這次收集的型別——新生代收集，只回收Eden分割槽
- 這次收集花費的時間——0.0305171s，即30ms
列出了新生代收集中並行收集的詳細過程
- 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啟動後的時間。理想情況下，你希望它們快速結束，並且最好是同一時間結束。
列出了新生代GC中的一些任務：
- Code Root Fixup ：釋放用於管理並行垃圾收集活動的資料結構，應該接近於0，該步驟是線性執行的；
- Code Root Purge：清理更多的資料結構，應該很快，耗時接近於0，也是線性執行。
- Clear CT：清理card table
包含一些擴充套件功能
- 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列表。
展示了不同代的大小變化，以及堆大小的自適應調整。
- 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點展示了本次新生代垃圾收集的時間
- user=0.8：垃圾收集執行緒在新生代垃圾收集過程中消耗的CPU時間，這個時間跟垃圾收集執行緒的個數有關，可能會比real time大很多；
- sys=0.0：核心態執行緒消耗的CPU時間
  -real=0.03：本次垃圾收集真正消耗的時間；

併發垃圾收集

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

標誌著併發垃圾收集階段的開始：
- GC pause(G1 Evacuation Pause)(young)(initial-mark)：為了充分利用STW的機會來trace所有可達（存活）的物件，initial-mark階段是作為新生代垃圾收集中的一部分存在的（搭便車）。initial-mark設定了兩個TAMS（top-at-mark-start）變數，用來區分存活的物件和在併發標記階段新分配的物件。在TAMS之前的所有物件，在當前週期內都會被視作存活的。
表示第併發標記階段做的第一個事情：根分割槽掃描
- GC concurrent-root-region-scan-start：根分割槽掃描開始，根分割槽掃描主要掃描的是新的survivor分割槽，找到這些分割槽內的物件指向當前分割槽的引用，如果發現有引用，則做個記錄；
- GC concurrent-root-region-scan-end：根分割槽掃描結束，耗時0.0030613s
表示併發標記階段
- 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
重新標記階段，會Stop the World
- Finalize Marking：Finalizer列表裡的Finalizer物件處理，耗時0.0014099s；
- GC ref-proc：引用（soft、weak、final、phantom、JNI等等）處理，耗時0.0000480s；
- Unloading：類解除安裝，耗時0.0025840s；
- 除了前面這幾個事情，這個階段最關鍵的結果是：繪製出當前併發週期中整個堆的最後面貌，剩餘的SATB緩衝區會在這裡被處理，所有存活的物件都會被標記；
清理階段，也會Stop the World
- 計算出最後存活的物件：標記出initial-mark階段後分配的物件；標記出至少有一個存活物件的分割槽；
- 為下一個併發標記階段做準備，previous和next點陣圖會被清理；
- 沒有存活物件的老年代分割槽和巨型物件分割槽會被釋放和清理；
- 處理沒有任何存活物件的分割槽的RSet；
- 所有的老年代分割槽會按照自己的存活率（存活物件佔整個分割槽大小的比例）進行排序，為後面的CSet選擇過程做準備；
併發清理階段
- GC concurrent-cleanup-start：併發清理階段啟動。完成第5步剩餘的清理工作；將完全清理好的分割槽加入到二級free列表，等待最終還會到總體的free列表；
- GC concurrent-cleanup-end：併發清理階段結束，耗時0.0012954s

混合收集

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