GC日誌分析

輸出GC日誌

咱們可使用以下參數開啓GC日誌的輸出：

• -XX:+PrintGC 輸出GC日誌
• -XX:+PrintGCDetails 輸出GC的詳細日誌
• -XX:+PrintGCTimeStamps輸出GC的時間戳（以基準時間的形式）
• -XX:+PrintGCDateStamps輸出GC的時間戳（以日期的形式，如2013-05-04T21:53:59.234+0800）
• -XX:+PrintHeapAtGC 在進行GC的先後打印出堆的信息
• -Xloggc:/logs/gc.log GC日誌輸出路徑

日誌分析

先看一段日誌：

2019-07-30T21:36:29.782+0800: 8.836: [GC (Allocation Failure) --[PSYoungGen: 4581K->4581K(9216K)] 12773K->12781K(19456K), 0.0015296 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-07-30T21:36:29.783+0800: 8.838: [Full GC (Ergonomics) [PSYoungGen: 4581K->0K(9216K)] [ParOldGen: 8200K->2817K(10240K)] 12781K->2817K(19456K), [Metaspace: 3201K->3201K(1056768K)], 0.0048723 secs] [Times: user=0.16 sys=0.00, real=0.01 secs] 
複製代碼

第一行：

• 2019-07-30T21:36:29.782+0800: GC日誌的時間戳。
• 8.836: JVM從開始運行以來通過的秒數。
• [GC (Allocation Failure) GC類型，Allocation Failure 表示因爲內存分配失敗而致使的GC。
• [PSYoungGen: 4581K->4581K(9216K)] PSYoungGen 表示年輕代，4581K 開始GC前內存佔用 -> 4581K GC後內存佔用，(9216K) Young區總大小。
• 12773K->12781K(19456K) 12773K GC前堆內存佔用 ->12781K GC後堆內存佔用，(19456K) 堆總大小。
• 0.0015296 secs 本次GC耗時。
• [Times: user=0.16 sys=0.00, real=0.01 secs] 具體的GC耗時信息，分別表明用戶態消耗的CPU時間、內核態消耗的CPU時間以及GC操做從開始到結束所通過的真實時間。CPU時間與真實時間的區別是，真實時間包括了非運算的等待耗時，如等待磁盤I/O、等待線程阻塞，而CPU時間不包括這些耗時，但當系統又多CPU或多核的話，多線程操做會疊加這些CPU時間，因此看到user或sys時間超過real時間是徹底正確的。

第二行：

• [Full GC (Ergonomics) 標識了本次發生的是一次FullGC。
• [ParOldGen: 8200K->2817K(10240K)] 老年代在發生GC先後的內存變化。
• [Metaspace: 3201K->3201K(1056768K)] metaspace區域在發生GC先後的內存變化。

G1收集器日誌

G1收集器的日誌相比其餘收集器的日誌有很大的不一樣，下面看一段G1收集器的GC日誌內容：

{Heap before GC invocations=12 (full 1):
 garbage-first heap   total 3145728K, used 336645K [0x0000000700000000, 0x00000007c0000000, 0x00000007c0000000)
  region size 1024K, 172 young (176128K), 13 survivors (13312K)
 Metaspace       used 29944K, capacity 30196K, committed 30464K, reserved 1077248K
  class space    used 3391K, capacity 3480K, committed 3584K, reserved 1048576K
2014-11-14T17:57:23.654+0800: 27.884: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 11534336 bytes, new threshold 15 (max 15)
- age   1:    5011600 bytes,    5011600 total
 27.884: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 1461, predicted base time: 35.25 ms, remaining time: 64.75 ms, target pause time: 100.00 ms]
 27.884: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 159 regions, survivors: 13 regions, predicted young region time: 44.09 ms]
 27.884: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 159 regions, survivors: 13 regions, old: 0 regions, predicted pause time: 79.34 ms, target pause time: 100.00 ms]
, 0.0158389 secs]
   [Parallel Time: 8.1 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 27884.5, Avg: 27884.5, Max: 27884.5, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.4, Avg: 0.8, Max: 1.2, Diff: 0.8, Sum: 3.1]
      [Update RS (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 1.4]
         [Processed Buffers: Min: 0, Avg: 2.8, Max: 5, Diff: 5, Sum: 11]
      [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.1, Max: 0.2, Diff: 0.2, Sum: 0.6]
      [Object Copy (ms): Min: 4.9, Avg: 5.1, Max: 5.2, Diff: 0.3, Sum: 20.4]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.4, Max: 1.3, Diff: 1.3, Sum: 1.4]
      [GC Worker Total (ms): Min: 6.4, Avg: 6.8, Max: 7.8, Diff: 1.4, Sum: 27.2]
      [GC Worker End (ms): Min: 27891.0, Avg: 27891.3, Max: 27892.3, Diff: 1.3]
   [Code Root Fixup: 0.5 ms]
   [Code Root Migration: 1.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 5.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 5.0 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.0 ms]
      [Free CSet: 0.2 ms]
   [Eden: 159.0M(159.0M)->0.0B(301.0M) Survivors: 13.0M->11.0M Heap: 328.8M(3072.0M)->167.3M(3072.0M)]
Heap after GC invocations=13 (full 1):
 garbage-first heap   total 3145728K, used 171269K [0x0000000700000000, 0x00000007c0000000, 0x00000007c0000000)
  region size 1024K, 11 young (11264K), 11 survivors (11264K)
 Metaspace       used 29944K, capacity 30196K, committed 30464K, reserved 1077248K
  class space    used 3391K, capacity 3480K, committed 3584K, reserved 1048576K
}
 [Times: user=0.05 sys=0.01, real=0.02 secs]
複製代碼

• garbage-first heap total 3145728K, used 336645K [0x0000000700000000, 0x00000007c0000000, 0x00000007c0000000) 標註了堆內存的總大小和使用狀況：total heap 3145728K，使用了336645K。
• region size 1024K, 172 young (176128K), 13 survivors (13312K) Region大小爲1M，青年代佔用了172個（共176128K），倖存區佔用了13個（共13312K）。
• Metaspace used 29944K, capacity 30196K, committed 30464K, reserved 1077248K class space used 3391K, capacity 3480K, committed 3584K, reserved 1048576K java 8的新特性，去掉永久區，添加了元數據區，這塊不是本文重點，再也不贅述。須要注意的是，之因此有committed和reserved，是由於沒有設置MetaspaceSize=MaxMetaspaceSize。
• [GC pause (G1 Evacuation Pause) (young) GC緣由，新生代minor GC。
• [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 1461, predicted base time: 35.25 ms, remaining time: 64.75 ms, target pause time: 100.00 ms] 發生minor GC和full GC時，全部相關region都是要回收的。而發生併發GC時，會根據目標停頓時間動態選擇部分垃圾對並多的Region回收，這一步就是選擇Region。pending_cards是關於RSet的Card Table。predicted base time是預測的掃描card table時間。
• [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 159 regions, survivors: 13 regions, predicted young region time: 44.09 ms] 這一步是添加Region到collection set，新生代一共159個Region，13個倖存區Region，這也和以前的（172 young (176128K), 13 survivors (13312K)）吻合。預計收集時間是44.09 ms。
• [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 159 regions, survivors: 13 regions, old: 0 regions, predicted pause time: 79.34 ms, target pause time: 100.00 ms] 這一步是對上面兩步的總結。預計總收集時間79.34ms。
• [Parallel Time: 8.1 ms, GC Workers: 4] 因爲收集過程是多線程並行（併發）進行，這裏是4個線程，總共耗時8.1ms（wall clock time）
• [GC Worker Start (ms): Min: 27884.5, Avg: 27884.5, Max: 27884.5, Diff: 0.1] 收集線程開始的時間，使用的是相對時間，Min是最先開始時間，Avg是平均開始時間，Max是最晚開始時間，Diff是Max-Min（此處的0.1貌似有問題）
• [Ext Root Scanning (ms): Min: 0.4, Avg: 0.8, Max: 1.2, Diff: 0.8, Sum: 3.1] 掃描Roots花費的時間，Sum表示total cpu time，下同。
• [Update RS (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 1.4] [Processed Buffers: Min: 0, Avg: 2.8, Max: 5, Diff: 5, Sum: 11] Update RS (ms)是每一個線程花費在更新Remembered Set上的時間。
• [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3] 掃描CS中的region對應的RSet，由於RSet是points-into，因此這樣實現避免了掃描old generadion region，可是會產生float garbage。
• [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6] 掃描code root耗時。code root指的是通過JIT編譯後的代碼裏，引用了heap中的對象。引用關係保存在RSet中。
• [Object Copy (ms): Min: 4.9, Avg: 5.1, Max: 5.2, Diff: 0.3, Sum: 20.4] 拷貝活的對象到新region的耗時。
• [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] 線程結束，在結束前，它會檢查其餘線程是否還有未掃描完的引用，若是有，則」偷」過來，完成後再申請結束，這個時間是線程以前互相同步所花費的時間。
• [GC Worker Other (ms): Min: 0.0, Avg: 0.4, Max: 1.3, Diff: 1.3, Sum: 1.4] 花費在其餘工做上（未列出）的時間。
• [GC Worker Total (ms): Min: 6.4, Avg: 6.8, Max: 7.8, Diff: 1.4, Sum: 27.2] 每一個線程花費的時間和。
• [GC Worker End (ms): Min: 27891.0, Avg: 27891.3, Max: 27892.3, Diff: 1.3] 每一個線程結束的時間。
• [Code Root Fixup: 0.5 ms] 用來將code root修正到正確的evacuate以後的對象位置所花費的時間。
• [Code Root Migration: 1.3 ms] 更新code root 引用的耗時，code root中的引用由於對象的evacuation而須要更新。
• [Code Root Purge: 0.0 ms] 清除code root的耗時，code root中的引用已經失效，再也不指向Region中的對象，因此須要被清除。
• [Clear CT: 0.2 ms] 清除card table的耗時。
• [Other: 5.8 ms] [Choose CSet: 0.0 ms] [Ref Proc: 5.0 ms] [Ref Enq: 0.1 ms] [Redirty Cards: 0.0 ms] [Free CSet: 0.2 ms] 其餘事項共耗時5.8ms，其餘事項包括選擇CSet，處理已用對象，引用入ReferenceQueues，釋放CSet中的region到free list。
• [Eden: 159.0M(159.0M)->0.0B(301.0M) Survivors: 13.0M->11.0M Heap: 328.8M(3072.0M)->167.3M(3072.0M)] 新生代清空了，下次擴容到301MB。