深刻理解G1的GC日誌

G1模式下總計有3中日誌級別，分別被稱爲：fine，finer，finest。

fine：fine模式打開方式是-verbose:gc，等價於-XX:+PrintGC。

finer：推薦，finer模式的打開方式是-XX:+PrintGCDetails。

finest：finest模式打開方式是-XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest。

G1模擬下主要有四種回收方式：

Young GC：全部Eden區域滿了後觸發，並行收集，且徹底STW。

併發標記週期：它的第一個階段初始化標記和YGC一塊兒發生，這個週期的目的就是找到回收價值最大的Region集合（垃圾不少，存活對象不多），爲接下來的Mixed GC服務。筆者以前有文章對其進行詳細描述，請戳：深(淺)入(出)剖析G1（Garbage First）。

Mixed GC：回收全部年輕代的Region和部分老年代的Region，Mixed GC可能連續發生屢次。

Full GC：很是慢，對OLTP系統來講簡直就是災難，會STW且回收全部類型的Region。

本文以咱們最經常使用的finer模式來分析G1的GC日誌，咱們只須要增長JVM參數-XX:+PrintGCDetails就能看到相關GC日誌，

YGC

咱們首先分析YGC日誌，是G1模式下遇到的頻率最高的GC，GC日誌以下所示：

3.378: [GC pause (G1 Evacuation Pause) (young), 0.0015185 secs]
[Parallel Time: 0.7 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 3378.1, Avg: 3378.3, Max: 3378.6, Diff: 0.5]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6]
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: Min: 0, Avg: 0.2, Max: 1, Diff: 1, Sum: 1]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
[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: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.7]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[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.1, Avg: 0.4, Max: 0.6, Diff: 0.6, Sum: 1.8]
[GC Worker End (ms): Min: 3378.7, Avg: 3378.7, Max: 3378.8, Diff: 0.1]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.5 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.1 ms]
[Free CSet: 0.1 ms]
[Eden: 304.0M(304.0M)->0.0B(304.0M) Survivors: 2048.0K->2048.0K Heap: 304.5M(512.0M)->529.0K(512.0M)]
[Times: user=0.01 sys=0.00, real=0.00 secs]
這段日誌是典型的Evacuation階段日誌（GC pause (G1 Evacuation Pause) (young)）。Evacution這個詞在G1中出現的頻率很是高，中文意思是疏散，在G1中能夠理解爲拷貝&清理，就是把存活的對象拷貝到1個或者多個Region中，目標Region可能只是Young區，也多是Young區+Old區，取決於此次YGC是否有符合晉升到Old區的對象。

另外，咱們能夠看到這段GC日誌有層級關係，筆者如今將其抽取成以下樣式：

GC pause (G1 Evacuation Pause) (young)
├── Parallel Time
├── GC Worker Start
├── Ext Root Scanning
├── Update RS
├── Scan RS
├── Code Root Scanning
├── Object Copy
├── Code Root Fixup
├── Code Root Purge
├── Clear CT
├── Other
├── Choose CSet
├── Ref Proc
├── Ref Enq
├── Redirty Cards
├── Humongous Register
├── Humongous Reclaim
├── Free CSet
由這段GC日誌咱們可知，整個YGC由多個子任務以及嵌套子任務組成，且一些核心任務爲：Root Scanning，Update/Scan RS，Object Copy，CleanCT，Choose CSet，Ref Proc，Humongous Reclaim，Free CSet。

YGC第一行日誌以下所示，這行日誌告訴咱們，此次YGC是在JVM啓動後3.378秒的時候發生的，而且整個過程耗時0.0015185秒：

3.378: [GC pause (G1 Evacuation Pause) (young), 0.0015185 secs]
接下來，深刻解讀YGC全部的子任務，即YGC都經歷過的階段。

Parallel Time

GC日誌以下所示，這段日誌告訴咱們，本次YGC總計由4個GC線程並行收集，並總計消耗時間0.7毫秒：

[Parallel Time: 0.7 ms, GC Workers: 4]
接下來就是下面這段日誌，這段日誌告訴咱們幾個GC線程開始的最小時間、平均時間和最大時間（這個時間是相對於JVM啓動後到如今的毫秒數），最後的Diff:0.5表示幾個GC線程最大啓動時間差有0.5毫秒：

[GC Worker Start (ms): Min: 3378.1, Avg: 3378.3, Max: 3378.6, Diff: 0.5]
再而後就是下面這段GC日誌，這段日誌表示幾個GC線程ROOT掃描階段消耗的時間統計信息，從這行日誌可知，ROOT掃描平均耗時0.1毫秒：

[Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6]
接下來就是下面這段GC日誌，即更新RSet消耗的時間統計信息，RSet即Remember Sets，它是用來記錄引用指向一個Region的跟蹤信息的數據結構。咱們看到後面還有一段Processed Buffers的日誌，Mutator線程會記錄對象圖的變化，JVM將這些變化的track信息記錄在被稱爲Update Buffers中。這個Update RS的子任務Processed Buffers就是負責處理這個Update Buffers的，從而將全部Region的RSets更新到一致的狀態：

[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: Min: 0, Avg: 0.2, Max: 1, Diff: 1, Sum: 1]
以下圖所示，咱們假設O1，即紫色塊就是某一個Old類型的Region，而綠色塊就是某一個Eden類型的Region：

深刻理解G1的GC日誌
Eden&Old
若是程序中執行了O1.attr=E1，即O1有對E1的引用，那麼Card Table就會記錄下來。而Remember Sets包含了對Card Table中這個Card的引用：

深刻理解G1的GC日誌
Update RS
接下來就是Scan RS階段，這個階段會掃描遍歷Remember Sets。由上圖可知，一個Region的RSet包含了指向這個Region的引用的Cards，這個階段就是掃描RSet中這些Cards，從而找出任何有指向CSet中全部Region的引用。經過這一步就能知道，Eden區哪些對象被老年代引用，從而不會在GC時回收掉：

[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
再而後就是對象拷貝階段。這個階段會將前面掃描到的存活的對象拷貝到目標Region中，多是Survivor類型Region，也多是Old類型Region（若是達到晉升條件的話），並記錄拷貝過程消耗的時間統計信息：

[Object Copy (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
以下圖所示，就是對象拷貝先後對比圖：

深刻理解G1的GC日誌
對象拷貝前
深刻理解G1的GC日誌
對象拷貝後
接下來就是Parallel階段最後幾個子任務，GC Worker Total表示GC線程整個生命週期總計消耗的時間，而GC Worker End表示GC線程完成任務中止的時間（這個時間是相對於JVM進程啓動後的毫秒數）：

[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.1, Avg: 0.4, Max: 0.6, Diff: 0.6, Sum: 1.8]
[GC Worker End (ms): Min: 3378.7, Avg: 3378.7, Max: 3378.8, Diff: 0.1]

Clear CT

CT就是Card Table，即清理Card Table消耗的時間。這個階段對應的GC日誌以下所示：

[Clear CT: 0.1 ms]

Other

最後一個階段Other，這個階段也包含了比較多的子任務，接下來一個一個進行剖析。

第一個就是Choose Cset，很好理解，就是選擇哪些Region做爲CSet一部分須要的時間，G1會根據用戶設置的停頓時間來決定Region的數量：

[Choose CSet: 0.0 ms]
再而後就是Ref Proc，即處理引用對象消耗的時間，多是Weak、Soft、Phantom引用，強烈建議配置參數：-XX:+ParallelRefProcEnabled（這個參數默認是關閉的），即讓這個階段並行處理：

[Ref Proc: 0.5 ms]
下一步就是超大（humongous）對象的處理，YGC階段若是發現某些H區域的對象都不是存活對象，就會回收掉這些對象佔用的空間：

[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.1 ms]
Other階段最後一個子任務就是Free CSet，即釋放掉CSet中Region佔用的內存空間所消耗的時間（前面的Object Copy已經將CSet中存活的對象拷貝到了目標Region中，因此這裏須要回收Region佔用的內存空間）：

[Free CSet: 0.1 ms]

Eden

這一行GC日誌很是容易理解，和之前的ParNew+CMS或者默認的PS垃圾回收幾乎同樣的，Eden: 304.0M(304.0M)->0.0B(304.0M)表示整個Eden區從佔用304.0M到回收後的0.0B，而且GC先後 整個Eden區大小沒有變化，仍是304.0M，最後的Heap: 304.5M(512.0M)->529.0K(512.0M)表示整個堆回收前佔用304.5M，回收後佔用529.0K，而且整個堆大小是512.0M：

[Eden: 304.0M(304.0M)->0.0B(304.0M) Survivors: 2048.0K->2048.0K Heap: 304.5M(512.0M)->529.0K(512.0M)]
併發標記週期

上面提分析的日誌所有是YGC階段的日誌，G1模式下還有一個重要的週期，即全局併發標記週期，其GC日誌以下所示：

這一行日誌是全局併發標記的第一個階段，即初始化標記，是伴隨YGC一塊兒發生的，後面的857M->617M表示YGC發生先後堆內存變化，0.0112237表示YGC的耗時

[GC pause (G1 Evacuation Pause) (young) (initial-mark) 857M->617M(1024M), 0.0112237 secs]

開始併發ROOT區域掃描

[GC concurrent-root-region-scan-start]

結束併發ROOT區域掃描，並統計這個階段的耗時

[GC concurrent-root-region-scan-end, 0.0000525 secs]
[GC concurrent-mark-start]
[GC concurrent-mark-end, 0.0083864 secs]

最終標記階段完成併發標記階段後遺留的工做，即SATB buffer處理，並統計這個階段耗時

[GC remark, 0.0038066 secs]

清理階段會根據全部Region標記信息，計算出每一個Region存活對象信息，而且把Region根據GC回收效率排序

[GC cleanup 680M->680M(1024M), 0.0006165 secs]
Mixed GC

Evacuation Pause除了是YGC觸發以外，還多是Mixed GC（[GC pause (G1 Evacuation Pause) (mixed)），日誌以下所示，Mixed GC的整個子任務和YGC徹底同樣，只是回收的範圍（CSet）不同而已，YGC只回收Young區，而Mixed GC回收Young區+部分Old區：

29.268: [GC pause (G1 Evacuation Pause) (mixed), 0.0059011 secs]
[Parallel Time: 5.6 ms, GC Workers: 4]
… …
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.3 ms]
… …
[Eden: 14.0M(14.0M)->0.0B(156.0M) Survivors: 10.0M->4096.0K Heap: 165.9M(512.0M)->148.7M(512.0M)]
[Times: user=0.02 sys=0.01, real=0.00 secs]
Full GC

最後一種垃圾收集方式即FullGC，事實上，在G1的正常工做流程中沒有Full GC的概念，只有在G1搞不定的狀況下（或者主動觸發），纔會發生的GC方式。日誌以下，也很是容易理解，由第一行日誌可知，此次的FullGC是由System.gc()觸發的：

4.358: [Full GC (System.gc()) 298M->509K(512M), 0.0101774 secs]
[Eden: 122.0M(154.0M)->0.0B(230.0M) Survivors: 4096.0K->0.0B Heap: 298.8M(512.0M)->509.4K(512.0M)], [Metaspace: 3308K->3308K(1056768K)]
[Times: user=0.01 sys=0.00, real=0.01 secs]
下面這段日誌是G1搞不定的狀況下發觸發的FullGC，從第二行日誌能夠看出，Mixed GC先後，堆大小都是99G，說明沒有任何回收效果，而堆由已經滿了，因此觸發了Full GC：

805.815: [GC pause (G1 Evacuation Pause) (young) 96G->74G(100G), 2.4778659 secs] 813.964: [GC pause (G1 Evacuation Pause) (mixed)-- 97G->99G(100G), 23.7970094 secs]837.762: [GC pause (G1 Evacuation Pause) (mixed)-- 99G->99G(100G), 32.0781615 secs]869.842: [Full GC (Allocation Failure) 99G->62G(100G), 169.3897706 secs]