九、G1收集器-GC日志

1、Evacuation Pause（转移暂停-纯年轻代模式）

      在应用程序刚启动时，G1还未执行过并发阶段，也就没有获得额外的信息，处于初始的纯年轻代模式。在年轻代空间用完之后, 应用线程被暂停, 年轻代堆区中的存活对象被复制到存活区, 如果还没有存活区,则选择任意一部分空闲的小堆区用作存活区。复制的过程称为转移(Evacuation), 这和前面讲过的年轻代收集器基本上是一样的工作原理。
Evacuation Pause的完整日志：
2019-06-21T16:44:44.031+0800: 2.323: [GC pause (G1 Evacuation Pause) (young), 0.0079227 secs]：转移暂停，只清理年轻代，暂停在JVM启动232.3ms开始，耗费时间0.0079227秒。
       [Parallel Time: 5.4 ms, GC Workers: 8]：表明后面的活动由8个 Worker 线程并行执行, 消耗时间为5.4ms(real time)。
             [GC Worker Start (ms): Min: 2323.1, Avg: 2323.6, Max: 2324.5, Diff: 1.3]：GC的worker线程开始启动时，相对于 pause 开始的时间戳。如果 Min 和 Max 差别很大，则表明本机其他进程所使用的线程数量过多，挤占了GC的CPU时间。
             [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 1.1, Diff: 1.1, Sum: 2.3]：用了多长时间来扫描堆外(non-heap)的root, 如 classloaders, JNI引用, JVM的系统root等。后面显示了运行时间, “Sum” 指的是CPU时间。
             [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.5]
                   [Processed Buffers: Min: 0, Avg: 1.2, Max: 4, Diff: 4, Sum: 10]
             [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: 1.2, Max: 4.3, Diff: 4.3, Sum: 9.2]：用了多长时间来扫描实际代码中的 Root。
             [Object Copy (ms): Min: 0.1, Avg: 2.8, Max: 3.8, Diff: 3.7, Sum: 22.4]：用了多长时间来拷贝收集区内的存活对象。
             [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.7, Diff: 0.7, Sum: 2.5]：GC的worker线程用了多长时间来确保自身可以安全地停止, 这段时间什么也不用做, stop 之后该线程就终止运行了。
             [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]：一些琐碎的小活动,在GC日志中不值得单独列出来。
             [GC Worker Total (ms): Min: 4.0, Avg: 4.6, Max: 5.0, Diff: 1.0, Sum: 37.0]：GC的worker 线程的工作时间总计。
             [GC Worker End (ms): Min: 2328.2, Avg: 2328.2, Max: 2328.5, Diff: 0.3]：GC的worker 线程完成作业的时间戳。通常来说这部分数字应该大致相等，否则就说明有太多的线程被挂起，很可能是因为坏邻居效应所导致的。
       [Code Root Fixup: 0.3 ms]：释放用于管理并行活动的内部数据。一般都接近于零。这是串行执行的过程。
       [Code Root Purge: 0.0 ms]：清理其他部分数据，也是非常快的, 但如非必要则几乎等于零。这是串行执行的过程。
       [Clear CT: 0.2 ms]
       [Other: 2.1 ms]：其他活动消耗的时间, 其中有很多是并行执行的。
             [Choose CSet: 0.0 ms]
             [Ref Proc: 1.7 ms]：处理非强引用(non-strong)的时间: 进行清理或者决定是否需要清理。
             [Ref Enq: 0.0 ms]：用来将剩下的 non-strong 引用排列到合适的 ReferenceQueue中。
             [Redirty Cards: 0.2 ms]
             [Humongous Reclaim: 0.0 ms]
             [Free CSet: 0.1 ms]：将回收集中被释放的小堆归还所消耗的时间, 以便他们能用来分配新的对象。
       [Eden: 68.0M(68.0M)->0.0B(66.0M) Survivors: 8192.0K->10.0M Heap: 81.7M(128.0M)->15.7M(128.0M)]：暂停之前和暂停之后，Eden区的使用量（总容量）、Survivor区的使用量、整个堆的使用量（总容量）。
    [Times: user=0.06 sys=0.00, real=0.01 secs]：GC线程消耗的CPU总时间，系统调用和系统等待时间，应用暂停时间。

2、Concurrent Marking（并发标记）

       当堆内存的总体使用比例达到一定数值时,就会触发并发标记。默认值为 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]

参考资料
1.《深入理解Java虚拟机：JVM高级特性与最佳实践》（第2版）；
2.Java HotSpot Virtual Machine Garbage Collection Tuning Guide Release 8；
3.Java垃圾收集必备手册。