java g1 gc ref proc_九、G1收集器-GC日志

当堆内存的总体使用比例达到一定数值时,就会触发并发标记。默认值为 45%，可以通过JVM参数InitiatingHeapOccupancyPercent进行设置。

并发标记日志：

初始标记：标记从GC Root直接可对象，在CMS中需要一次STW，G1中通常是在转移暂停的同时处理这些事情，所以这个阶段的日志基本类似转移暂停的日志。

2019-06-21T16:44:44.133+0800: 2.425: [GC pause (Metadata GC Threshold) (young) (initial-mark), 0.0083681 secs]

[Parallel Time: 6.9 ms, GC Workers: 8]

[GC Worker Start (ms): Min: 2425.1, Avg: 2425.5, Max: 2425.8, Diff: 0.7]

[Ext Root Scanning (ms): Min: 0.7, Avg: 2.9, Max: 6.5, Diff: 5.7, Sum: 23.4]

[Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6]

[Processed Buffers: Min: 0, Avg: 1.0, Max: 3, Diff: 3, Sum: 8]

[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.1, Max: 0.4, Diff: 0.4, Sum: 1.1]

[Object Copy (ms): Min: 0.0, Avg: 3.1, Max: 5.2, Diff: 5.2, Sum: 24.5]

[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 1.5]

[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]

[GC Worker Total (ms): Min: 6.1, Avg: 6.4, Max: 6.7, Diff: 0.7, Sum: 51.2]

[GC Worker End (ms): Min: 2431.8, Avg: 2431.9, Max: 2431.9, Diff: 0.0]

[Code Root Fixup: 0.3 ms]

[Code Root Purge: 0.0 ms]

[Clear CT: 0.2 ms]

[Other: 1.0 ms]

[Choose CSet: 0.0 ms]

[Ref Proc: 0.7 ms]

[Ref Enq: 0.0 ms]

[Redirty Cards: 0.2 ms]

[Humongous Reclaim: 0.0 ms]

[Free CSet: 0.1 ms]

[Eden: 34.0M(66.0M)->0.0B(69.0M) Survivors: 10.0M->7168.0K Heap: 49.7M(128.0M)->14.7M(128.0M)]

[Times: user=0.06 sys=0.01, real=0.00 secs]

Root Region扫描：

2019-06-21T16:44:44.142+0800: 2.434: [GC concurrent-root-region-scan-start]

2019-06-21T16:44:44.147+0800: 2.439: [GC concurrent-root-region-scan-end, 0.0050150 secs]

并发标记：

2019-06-21T16:44:44.147+0800: 2.439: [GC concurrent-mark-start]

2019-06-21T16:44:44.152+0800: 2.444: [GC concurrent-mark-end, 0.0053220 secs]

重新标记：

2019-06-21T16:44:44.152+0800: 2.444: [GC remark 2.444: [Finalize Marking, 0.0003697 secs] 2.444: [GC ref-proc, 0.0001033 secs] 2.445: [Unloading, 0.0026974 secs], 0.0034274 secs]

[Times: user=0.02 sys=0.00, real=0.01 secs]

清理：

2019-06-21T16:44:44.156+0800: 2.448: [GC cleanup 16M->14M(128M), 0.0008178 secs]

[Times: user=0.01 sys=0.00, real=0.00 secs]

2019-06-21T16:44:44.157+0800: 2.449: [GC concurrent-cleanup-start]

2019-06-21T16:44:44.157+0800: 2.449: [GC concurrent-cleanup-end, 0.0000185 secs]