【譯】深刻理解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面試題、我的成長和自我管理等主題，爲讀者提供一線開發者的工做和成長經驗，期待你能在這裏有所收穫。