Java GC Tuning Guide episode 1 - GC logging

Java的GC讓開發人員減少處理記憶體配置的負擔，但是GC的運作方式與調整也關係到整個Java程式的運作效率與穩定性。先前一直有點半逃避的忽視這部份的東西，大都是用網路搜尋到的一些既有調整參數直接設了，不過該來的終究是要來，只靠一些別人的設定與調整方法，果然還是難以達到最佳的情況。要設定針對自己開發的程式/系統的最佳GC設定，還是得自己來追蹤與分析。

既然要自己追蹤與分析GC的情況，首先就必須有可以分析的資料，而最直接有用的就是GC log。以下說明如何透過JVM option啟用GC log來紀錄GC的內容：

• -XX:+PrintGCDetails
• 啟用此參數可讓JVM輸出所有詳細的GC行為，包含GC的類型(一般 or Full, Full GC會造成程式/系統暫停)，以及JVM內各記憶體配置區塊的GC動作情況與耗費時間等，資訊相當完整。
• -XX:+PrintGCTimeStamps 與-XX:+PrintGCDateStamps
• 這兩個參數是讓JVM在輸出GC log時，也順便加上時間資訊；PrintGCTimeStamps 是以程式啟動時間的相對時間做紀錄，而PrintGCDateStamps則是以系統的絕對時間做紀錄。兩者可擇一或並存。加上時間紀錄有助於分析與判斷。
• -Xloggc:<file name>
• 預設啟用gc log時，是輸出到console上，但是這樣不便於閱讀與分析，所以此參數可以指定輸出到檔案上
• -XX:+UseGCLogFileRotation
• 使用上一個參數時，會將所有的gc log寫到同一個檔案。如果不想讓檔案不斷成長，可以使用此參數將gc log檔固定在一定數量大小。注意：使用此參數，也必須搭配以下兩個參數才能正確運作
• -XX:NumberOfGCLogFiles=<number of files>
• 指定要保留的gc log檔數量，預設為1
• -XX:GCLogFileSize=<file size>
• 指定要保留的單一gc log檔大小，預設512K，可用M or K指定大小，如128M。

設定好之後啟動程式，即可在指定檔案中存下完整的gc log。以下是gc log範例(注意：輸出格式可能因不同JVM版本而有所出入)：

 0.011: [G1Ergonomics (Heap Sizing) expand the heap, requested expansion amount: 128974848 bytes, attempted expansion amount: 128974848 bytes]
2014-10-27T13:49:46.166+0800: 1.114: [GC pause (young) 1.114: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 2283, predicted base time: 23.70 ms, remaining time: 176.30 ms, target pause time: 200.00 ms]
 1.114: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 14 regions, survivors: 0 regions, predicted young region time: 356.52 ms]
 1.114: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 14 regions, survivors: 0 regions, old: 0 regions, predicted pause time: 380.22 ms, target pause time: 200.00 ms]
, 0.0200610 secs]
   [Parallel Time: 13.7 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 1113.8, Avg: 1117.5, Max: 1123.2, Diff: 9.4]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 1.3, Max: 2.8, Diff: 2.8, Sum: 5.3]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 2.8, Max: 11, Diff: 11, Sum: 11]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.6, Diff: 0.6, Sum: 0.7]
      [Object Copy (ms): Min: 0.4, Avg: 5.6, Max: 10.8, Diff: 10.4, Sum: 22.6]
      [Termination (ms): Min: 0.0, Avg: 2.6, Max: 3.8, Diff: 3.8, Sum: 10.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: 4.1, Avg: 9.8, Max: 13.6, Diff: 9.5, Sum: 39.2]
      [GC Worker End (ms): Min: 1127.3, Avg: 1127.3, Max: 1127.5, Diff: 0.2]
   [Code Root Fixup: 0.3 ms]
   [Code Root Migration: 1.1 ms]
   [Clear CT: 0.1 ms]
   [Other: 4.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 4.6 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 14.0M(14.0M)->0.0B(15.0M) Survivors: 0.0B->2048.0K Heap: 14.0M(123.0M)->4084.5K(123.0M)]
 [Times: user=0.03 sys=0.01, real=0.02 secs] 

透過這些log資訊，就可以了解程式/系統運作時的gc行為，進而調整至最適合的設定。
當然，以人工方式來分析gc log，是很困難的，因此也有一些工具可以幫忙。 目前個人使用GCViewer來幫忙處理與分析，雖然不算是很完美，但是也幫了不少忙。