Java垃圾收集器——Parallel、G1收集器日志分析及性能調優示范

開發過程中，經常需要對GC的垃圾收集器參數不斷的進行動態調整，從而更充分的壓榨機器性能，提升應用效率。本文將從常見的Parallel/G1垃圾收集器的GC日志着手，分析GC日志的具體含義，以及示范如何根據GC日志調整參數。

1. 准備工作

(1) VM Options

應用程序需要設置如下參數，以便將GC信息數值至gc.log文件中，供后續分析。

-XX:+DisableExplicitGC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./logs -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:./logs/gc.log

(2) GC統計工具
為了更好的統計GC日志信息，我們將借助於GCViewer桌面軟件(開源，地址為：https://github.com/chewiebug/GCViewer)，下載之后執行maven clean package -Dmaven.test.skip=true即可完成程序的編譯，雙擊target文件夾下的gcviewer-1.36-SNAPSHOT.jar（具體名稱由下載的GCViewer版本確定）即可執行程序。

原GCViewer於2008年后停止維護，上文提供的倉庫為chewiebug維護的Fork版本。

(3) 機器信息

本機參數：

jdk版本:Java HotSpot(TM) 64-Bit Server VM (25.172-b11) for windows-amd64 JRE (1.8.0_172-b11).

(4) 測試程序

自行編寫的Flink應用（主要優點是：吃內存，加上寫文章時正好在家里學習Flink...）。

2. Parallel收集器

Java HotSpot(TM) 64-Bit Server VM (25.172-b11) for windows-amd64 JRE (1.8.0_172-b11), built on Mar 28 2018 21:21:52 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16768628k(8408808k free), swap 33535356k(23695248k free)
CommandLine flags: -XX:+DisableExplicitGC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=$./logs -XX:InitialHeapSize=268298048 -XX:MaxHeapSize=4292768768 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
2019-10-24T15:33:39.513+0800: 2.164: [GC (Allocation Failure) [PSYoungGen: 65536K->7875K(76288K)] 65536K->7891K(251392K), 0.0275982 secs] [Times: user=0.17 sys=0.00, real=0.03 secs] 
2019-10-24T15:33:41.320+0800: 3.970: [GC (Allocation Failure) [PSYoungGen: 73411K->10738K(76288K)] 73427K->12337K(251392K), 0.0147806 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2019-10-24T15:33:41.772+0800: 4.422: [GC (Metadata GC Threshold) [PSYoungGen: 22142K->6329K(76288K)] 23741K->7935K(251392K), 0.0076904 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2019-10-24T15:33:41.780+0800: 4.430: [Full GC (Metadata GC Threshold) [PSYoungGen: 6329K->0K(76288K)] [ParOldGen: 1606K->6175K(100352K)] 7935K->6175K(176640K), [Metaspace: 20679K->20679K(1067008K)], 0.0334417 secs] [Times: user=0.23 sys=0.00, real=0.03 secs] 
2019-10-24T15:33:42.076+0800: 4.726: [GC (Allocation Failure) [PSYoungGen: 65536K->10738K(132608K)] 71711K->64480K(232960K), 0.0512660 secs] [Times: user=0.06 sys=0.42, real=0.05 secs] 
2019-10-24T15:33:42.164+0800: 4.815: [GC (Allocation Failure) [PSYoungGen: 132594K->10738K(141824K)] 186336K->184366K(316416K), 0.1241149 secs] [Times: user=0.03 sys=0.94, real=0.12 secs] 
2019-10-24T15:33:42.288+0800: 4.939: [Full GC (Ergonomics) [PSYoungGen: 10738K->8672K(141824K)] [ParOldGen: 173628K->174573K(399872K)] 184366K->183245K(541696K), [Metaspace: 22192K->22192K(1069056K)], 0.0938949 secs] [Times: user=0.39 sys=0.13, real=0.09 secs] 
2019-10-24T15:33:42.415+0800: 5.066: [GC (Allocation Failure) [PSYoungGen: 139744K->120826K(320000K)] 314317K->312422K(719872K), 0.1433171 secs] [Times: user=0.00 sys=1.08, real=0.14 secs] 
2019-10-24T15:33:43.607+0800: 6.257: [GC (GCLocker Initiated GC) [PSYoungGen: 319994K->161768K(360960K)] 511592K->392382K(760832K), 0.2255222 secs] [Times: user=0.36 sys=1.39, real=0.22 secs] 
2019-10-24T15:33:45.921+0800: 8.572: [GC (Metadata GC Threshold) [PSYoungGen: 324597K->172709K(544768K)] 555211K->403387K(944640K), 0.1776332 secs] [Times: user=0.03 sys=1.16, real=0.18 secs] 
2019-10-24T15:33:46.099+0800: 8.749: [Full GC (Metadata GC Threshold) [PSYoungGen: 172709K->0K(544768K)] [ParOldGen: 230678K->398712K(628224K)] 403387K->398712K(1172992K), [Metaspace: 36781K->36523K(1081344K)], 0.2291498 secs] [Times: user=0.20 sys=1.25, real=0.23 secs] 
2019-10-24T15:33:50.564+0800: 13.214: [GC (Allocation Failure) [PSYoungGen: 326144K->88922K(569344K)] 790394K->553180K(1197568K), 0.0217578 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
Heap
 PSYoungGen      total 569344K, used 303805K [0x000000076ab80000, 0x00000007a2800000, 0x00000007c0000000)
  eden space 326144K, 65% used [0x000000076ab80000,0x0000000777d58c70,0x000000077ea00000)
  from space 243200K, 36% used [0x000000077ea00000,0x00000007840d6960,0x000000078d780000)
  to   space 226304K, 0% used [0x0000000794b00000,0x0000000794b00000,0x00000007a2800000)
 ParOldGen       total 628224K, used 464258K [0x00000006c0200000, 0x00000006e6780000, 0x000000076ab80000)
  object space 628224K, 73% used [0x00000006c0200000,0x00000006dc760a18,0x00000006e6780000)
 Metaspace       used 55000K, capacity 59794K, committed 60032K, reserved 1099776K
  class space    used 8350K, capacity 10033K, committed 10112K, reserved 1048576K

上面所示內容為設置基本VM Options，啟動應用后的GC日志，查看可知在沒有指定垃圾收集器的情況下，jdk默認選擇了ParallelGC收集器(在沒有指定垃圾收集器的時候，並且內存較為充足的情況下，jdk會默認選擇ParallelGC)。

2.1 Young GC

截取一條日志進行分析（為了更好的展示，將單挑日志拆分為三段，並使用上標表示每個字段的位置）：

2019-10-24T15:33:42.076+0800¹: 4.726²:
[GC³ (Allocation Failure⁴) [PSYoungGen⁵: 65536K->10738K⁶(132608K⁷)] 71711K->64480K⁸(232960K⁹), 0.0512660 secs¹⁰]
[Times: user=0.06 sys=0.42, real=0.05 secs¹¹]

針對此條日志，進行具體分析：

(1) 2019-10-24T15:33:42.076+0800:當前GC事件發生時的UTC時間戳；
(2) 4.726: 當前GC發生時，JVM的啟動事件(單位為s)；
(3) GC: 用於區分Young GC與Full GC，當前GC為Young GC；
(4) Allocation Failure: 當前GC的產生原因(新生代中空間不足以為新對象分配空間)；
(5) PSYoungGen: 垃圾收集器的名稱；
(6) 65536K->10738K: GC前后新生代的內存空間使用量；
(7) 132608K: 新生代總內存量；
(8) 71711K->64480K: GC前后應用堆內存的變化情況(包括新生代和老年代)；
(9) 232960K: JVM堆的可用內存；
(10) 0.0512660 secs: 本次GC耗時，單位為s；
(11) [Times: user=0.06 sys=0.42, real=0.05 secs]:GC事件的耗時;

• user: 此次GC，所有GC線程消耗的CPU事件總和；
• sys: 此次GC，操作系統調用等事件所消耗的時間總和；
• real: 應用停頓的總時間，在並行的GC中，此數值應該接近(user + sys) / GCThreads，即單核上的平均停頓時間。

綜上所述，在GC前總共使用了71711K堆內存，其中新生代使用了65536K，則老年代使用了6175K。GC后，新生代釋放了65536-10738=54798K內存，但是堆內存僅釋放了71711-64480=7231K內存，說明此次GC，有47567K的對象從新生代升級到了老年代。變化情況如下圖所示：

2.2 Full GC

截取一條日志進行分析（為了更好的展示，將單挑日志拆分為三段，並使用上標表示每個字段的位置）：

2019-10-24T15:33:46.099+0800¹: 8.749²:
[Full GC³ (Metadata GC Threshold⁴) [PSYoungGen⁵: 172709K->0K⁶(544768K⁷)] [ParOldGen⁸: 230678K->398712K⁹(628224K¹⁰)] 403387K->398712K¹⁰(1172992K¹¹),
[Metaspace¹²: 36781K->36523K¹³(1081344K¹⁴)], 0.2291498 secs¹⁵] [Times: user=0.20 sys=1.25, real=0.23 secs]¹⁶

針對此條日志，進行具體分析：

(1) 2019-10-24T15:33:46.099+0800: 當前GC事件發生時的UTC時間戳；
(2) 8.749: 當前GC發生時，JVM的啟動事件(單位為s)；
(3) Full GC: 用於區分Young GC與Full GC，當前GC為Full GC；
(4) Metadata GC Threshold: 當前GC的產生原因(Metaspace空間占用達到閾值)；
(5) PSYoungGen: 新生代垃圾收集器名稱；
(6) 172709K->0K: Full GC時，新生代內存空間將被清空；
(7) 544768K: 新生代總內存量；
(8) ParOldGen: 老年代垃圾收集器名稱；
(9) 230678K->398712K: Full GC時，老年代內存空間變化情況；
(10) 628224K: 老年代總內存量；
(11) 403387K->398712K: GC前后堆內存的變化情況；
(12) 1172992K: JVM堆的可用內存；
(13) Metaspace: metaspace空間；
(14) 36781K->36523K: metaspace空間的變化情況；
(15) 1081344K: metadata的保留空間（metaspace時從jvm進程的虛擬地址空間中分離出來的）；
(16) 0.2291498 secs: 當前GC的耗時，單位為s；
(17) [Times: user=0.20 sys=1.25, real=0.23 secs]: 具體含義參見Young GC解釋。

由以上數據可知，在此次Full GC的過程中，Young區域的數據被清空，但是Old區以及Metaspace區均進行擴容以便存放更多數據。

3. G1收集器

並發收集器主要有CMS以及G1收集器，因為在jdk 1.8上，G1收集器已經得到較大的完善，因此舍棄CMS收集器的日志分析，直接分析G1收集器（在VM Options中添加-XX:+UseG1GC即可）。如果讀者想使用CMS收集器，只需要在VM Options中添加-XX:+UseConcMarkSweepGC即可。

2019-10-24T16:52:43.377+0800: 7.865: [GC pause (G1 Evacuation Pause) (young), 0.0197774 secs]
   [Parallel Time: 10.9 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 7865.0, Avg: 7865.0, Max: 7865.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.7, Avg: 1.7, Max: 5.7, Diff: 4.9, Sum: 13.9]
      [Update RS (ms): Min: 0.0, Avg: 1.0, Max: 2.4, Diff: 2.4, Sum: 7.8]
         [Processed Buffers: Min: 0, Avg: 11.3, Max: 29, Diff: 29, Sum: 90]
      [Scan RS (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 2.7]
      [Code Root Scanning (ms): Min: 0.0, Avg: 2.1, Max: 8.3, Diff: 8.3, Sum: 16.9]
      [Object Copy (ms): Min: 0.0, Avg: 5.4, Max: 7.8, Diff: 7.8, Sum: 43.3]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]
         [Termination Attempts: Min: 1, Avg: 2.4, Max: 4, Diff: 3, Sum: 19]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
      [GC Worker Total (ms): Min: 10.6, Avg: 10.7, Max: 10.7, Diff: 0.1, Sum: 85.6]
      [GC Worker End (ms): Min: 7875.7, Avg: 7875.7, Max: 7875.8, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 8.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 7.6 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.3 ms]
   [Eden: 161.0M(161.0M)->0.0B(182.0M) Survivors: 13.0M->21.0M Heap: 626.5M(1066.0M)->474.0M(1066.0M)]
 [Times: user=0.05 sys=0.00, real=0.02 secs] 

G1的垃圾收集過程，因為其特殊的內存划分，導致存在很多細微的步驟。
我們截取其主要部分進行分析：

(1) [GC pause (G1 Evacuation Pause) (young), 0.0197774 secs]: 說明當前GC為Young GC，cpu耗時0.0197774s；
(2) [Parallel Time: 10.9 ms, GC Workers: 8]: 此次GC停頓的實際時間為10.9ms，共有8個線程參與清理工作；
(3) Eden: 161.0M(161.0M)->0.0B(182.0M) Survivors: 13.0M->21.0M Heap: 626.5M(1066.0M)->474.0M(1066.0M):
此段說明Eden區的內存共計161.0M被釋放了，有部分對象轉移至Survivors區導致Survivors區內存擴大，堆內存因為Eden區釋放資源的緣故總量變小(空間未發生變化)。

因為在當前的GC日志抓取中，未存在Mixed GC，因此此處就不對Mixed GC日志進行分析(感興趣的讀者可以在較大的程序中獲取G1 GC日志進行進一步分析)。雖然G1的GC日志雖然步驟很清晰，但是每次GC均會有大量日志產生，不便於根據日志進行分析，因此我推薦使用GCViewer可視化工具輔助進行分析。導入GC日志，信息如下圖所示：

圖中左側詳細羅列了GC的詳細情況，包括GC Pause(停頓應用的GC數據)以及Concurrent GCs(與應用並發執行的GC數據)。右側則概要的描述了應用開始執行后的吞吐量(Throughput：95.15%)，導致應用停頓的GC次數(Number of gc pauses：8)以及GC停頓時間(Accumulated pauses: 0.36s)。通過以上信息，就可以對G1收集器在應用執行過程的表現有一個清晰的認識。

3. 性能優化

直接根據GC日志進行針對性調優較為困難(生產環境的GC日志量比較大，尤其是CMS/G1的GC日志)，因此建議將GC日志導出，通過圖形化工具GCViewer進行匯總統計，得到可靠的報表信息。
使用GCViewer進行調優時，一般關注以下幾個指標：Throughput(吞吐量)，Number of gc pauses(GC停頓數量)以及Accumulated pauses(GC停頓總耗時)。

3.1 Parallel收集器調優

調優參數：

• -XX:MetaspaceSize: 在應用啟動初期，普遍存在因為metaspace空間達到閾值引發的GC，因此可以合理設置Metaspace空間規避此類GC；
• -XX:MaxGCPauseMillis: 最大GC停頓時間，這是個軟目標，JVM將盡可能（但不保證）停頓小於這個時間;
• -XX:GCTimeRatio: 垃圾收集時間占總時間的比例(假設GCTimeRatio設置為N，則垃圾收集時間占總時間的比例為1 / (1 + N))

Parallel收集器是自適應收集器，一般設置MaxGCPauseMillis以及GCTimeRatio，即可由jdk進行動態調整，用戶可以根據GC日志得到最佳的停頓時間和吞吐量設置方案。

3.2 G1收集器調優

關於G1垃圾收集器的調優，建議有以下兩條：

• 年輕代大小：避免使用-Xmn選項或-XX:NewRatio 等其他相關選項顯式設置年輕代大小，因為固定年輕代的大小會覆蓋暫停時間目標。
• 暫停時間目標：每當對垃圾回收進行評估或調優時，都會涉及到延遲與吞吐量的權衡。G1是增量垃圾回收器，其吞吐量目標是90% 的應用程序時間和10%的垃圾回收時間。因此，暫停時間目標不要太嚴苛。目標太過嚴苛表示您願意承受更多的垃圾回收開銷，而這會直接影響到吞吐量。

如果對於性能有着嚴苛的要求，可以參照https://toutiao.io/k/8b0dxca的做法，開啟G1的所有參數:

-Xmx30g -Xms30g
-XX:MaxDirectMemorySize=30g
-XX:+UseG1GC
-XX:+UnlockExperimentalVMOptions
-XX:MaxGCPauseMillis=90
-XX:G1NewSizePercent=8
-XX:InitiatingHeapOccupancyPercent=30
-XX:+ParallelRefProcEnabled
-XX:ConcGCThreads=4
-XX:ParallelGCThreads=16
-XX:MaxTenuringThreshold=1
-XX:G1HeapRegionSize=32m
-XX:G1MixedGCCountTarget=64
-XX:G1OldCSetRegionThresholdPercent=5

其中重點需要調優的參數有：

• G1NewSizePercent ：G1的Young區大小是通過算法來自適應確定的, 也就是根據之前Young區GC的耗時來確定之后的Young大小,如果耗時過長,則調小Young區,耗時過短,則調大Young區. 這個參數表示Young的最小百分比；
• InitiatingHeapOccupancyPercent: 當占用內存超過這個百分比的時候, G1開始執行多次Mixed GC來整理老年代內存碎片；
• G1MixedGCCountTarget: 當占用內存超過InitiatingHeapOccupancyPercent閥值時, 最多通過多少次Mixed GC來將內存控制在閥值之下；
• MaxTenuringThreshold: 當一個對象gc的代數超過這個值的時候, 會將對象從young區挪到old區；
• G1HeapRegionSize: 表示G1將每個Region切分成多大, 注意一定要寫單位, 例如32m。

逐個調整以上參數並收集GC日志，通過GCViewer收集各項指標，最終根據實際情況挑選滿意的G1收集器參數即可。

PS:
如果您覺得我的文章對您有幫助，請關注我的微信公眾號，謝謝!