G1垃圾回收日志分析

标准 gc 日志

使用G1垃圾回收器最难的地方是读懂回收日志。G1回收虽然也是分代的，但是打印出来的日志却不像其他回收器那样明显。所以需要好好配置JVM参数才行。先看下面一段日志，这段日志是通过配置好的JVM参数输出的，分隔明确，很容易分辨出每次回收过程。

 # 每次回收以 花括号开始 
 # invocations=2302 代表第2302次回收
{
   Heap before GC invocations=2302 (full 0):
 garbage-first heap   total 32768K, used 30719K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)
  region size 1024K, 18 young (18432K), 0 survivors (0K)
 Metaspace       used 7722K, capacity 7936K, committed 8064K, reserved 1056768K
  class space    used 1013K, capacity 1068K, committed 1152K, reserved 1048576K
  # 代表是一次 yong GC ,原因是: 疏散停顿（Evacuation Pause）是将活着的对象从一个区域（young or young + old）拷贝到另一个区域的阶段。
2020-10-09T20:13:01.203-0800: 22.971: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0062834 secs]
	# 4 个线程回收
   [Parallel Time: 0.9 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 22970.7, Avg: 22970.8, Max: 22971.0, Diff: 0.3]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: 0.6]
      [Update RS (ms): Min: 0.5, Avg: 0.6, Max: 0.6, Diff: 0.1, Sum: 2.4]
         [Processed Buffers: Min: 4, Avg: 7.5, Max: 10, Diff: 6, Sum: 30]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [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.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
         [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.0]
      [GC Worker Total (ms): Min: 0.6, Avg: 0.8, Max: 0.9, Diff: 0.3, Sum: 3.2]
      [GC Worker End (ms): Min: 22971.6, Avg: 22971.6, Max: 22971.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 5.3 ms]
      [Evacuation Failure: 5.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   # 这一行比较简单，不再解释
   [Eden: 18.0M(18.0M)->0.0B(16.0M) Survivors: 0.0B->0.0B Heap: 30.0M(32.0M)->10.7M(32.0M)]
Heap after GC invocations=2303 (full 0):
 garbage-first heap   total 32768K, used 10994K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)
  region size 1024K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 7722K, capacity 7936K, committed 8064K, reserved 1056768K
  class space    used 1013K, capacity 1068K, committed 1152K, reserved 1048576K
}
 # 回收结束标志，各阶段耗时
 [Times: user=0.01 sys=0.00, real=0.00 secs] 

# 下面是一段mix gc ，以一个yong gc 开始，开始的原因是大对象分配失败 （G1 Humongous Allocation）
{
   Heap before GC invocations=2303 (full 0):
 garbage-first heap   total 32768K, used 20906K [0x00000007be000000, 0x00000007be100100, 0x00000007c0000000)
  region size 1024K, 9 young (9216K), 0 survivors (0K)
 Metaspace       used 7722K, capacity 7936K, committed 8064K, reserved 1056768K
  class space    used 1013K, capacity 1068K, committed 1152K, reserved 1048576K
  # 初始标记 + yong gc
2020-10-09T20:13:01.212-0800: 22.980: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0008588 secs]
   [Parallel Time: 0.7 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 22980.2, Avg: 22980.2, Max: 22980.2, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.9]
      [Update RS (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 1.0]
         [Processed Buffers: Min: 3, Avg: 4.5, Max: 5, Diff: 2, Sum: 18]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [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.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.2]
      [GC Worker Total (ms): Min: 0.6, Avg: 0.6, Max: 0.6, Diff: 0.1, Sum: 2.3]
      [GC Worker End (ms): Min: 22980.8, Avg: 22980.8, Max: 22980.8, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Re