G1垃圾回收器步骤

4443.554: [GC pause (G1 Evacuation Pause) (young), 0.0061966 secs]
   [Parallel Time: 4.2 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 4443554.1, Avg: 4443554.2, Max: 4443554.2, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 1.1, Avg: 1.2, Max: 1.8, Diff: 0.7, Sum: 9.7]
                      -- 扫描Roots花费的时间
      [Update RS (ms): Min: 0.6, Avg: 1.1, Max: 1.4, Diff: 0.8, Sum: 8.8]
                      -- Update RS (ms)是每个线程花费在更新Remembered Set上的时间。   
         [Processed Buffers: Min: 39, Avg: 43.4, Max: 47, Diff: 8, Sum: 347]
      [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.0]
                      -- 扫描CSet中的region对应的RSet，因为RSet是points-into，
                  --所以这样实现避免了扫描old generadion region但会产生float garbage
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
                  -- 扫描code root耗时。code root指的是经过JIT编译后的代码里，
                  --引用了heap中的对象。引用关系保存在RSet中。
      [Object Copy (ms): Min: 1.2, Avg: 1.3, Max: 1.4, Diff: 0.2, Sum: 10.7]
                  -- 拷贝活的对象到新region的耗时。  
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
                  -- 当worker线程完成了自己那部分对象的复制和扫描,就进入终止协议。
                --它查找未完成的工作(具体做了什么呢？), 一旦它完成就会再进入终止协议
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
                -- -所有查找工作的尝试次数(attempts to steal work).
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
      [GC Worker Total (ms): Min: 3.9, Avg: 4.0, Max: 4.1, Diff: 0.2, Sum: 31.7]
      [GC Worker End (ms): Min: 4443558.1, Avg: 4443558.2, Max: 4443558.2, Diff: 0.1]
   [Code Root Fixup: 0.3 ms]
        -- 用来将code root修正到正确的 evacuate 之后的对象位置所花费的时间
   [Code Root Purge: 0.0 ms]
        --清除code root的耗时code root中的引用已经失效，不再指向Region中的对象所以需要被清除
   [Clear CT: 0.3 ms]
        --清除 RSet 扫描元数据(scanning meta-data)的 card table 消耗的时间.
   [Other: 1.5 ms]
      [Choose CSet: 0.0 ms]
            --选定要进行垃圾回收的region集合时消耗的时间。通常很小在必须选择old区时会稍微长
      [Ref Proc: 0.2 ms]
            --处理 soft, weak, 等引用所花费的时间,不同于前面的GC阶段
      [Ref Enq: 0.0 ms]
            --将 soft, weak, 等引用放置到待处理列表(pending list)花费的时间
      [Redirty Cards: 0.1 ms]
            --在回收过程中被修改的card将会被重置为dirty
      [Humongous Register: 0.0 ms]
            -- JDK8u60提供了一个特性，巨型对象可以在新生代收集的时候被回收——
            --通过G1ReclaimDeadHumongousObjectsAtYoungGC设置，默认为true
      [Humongous Reclaim: 0.1 ms]
            -- 做下列任务的时间：确保巨型对象可以被回收、释放该巨型对象所占的分区，
            -- 重置分区类型，并将分区还到free列表，并且更新空闲空间大小
      [Free CSet: 0.5 ms]
            -- 将要释放的分区还回到free列表
   [Eden: 646.0M(646.0M)->0.0B(317.0M) Survivors: 21.0M->16.0M Heap: 1253.9M(2224.0M)->561.5M(2224.0M)]
 [Times: user=0.03 sys=0.01, real=0.00 secs]
4443.861: [GC pause (G1 Evacuation Pause) (mixed), 0.0058716 secs]
   [Parallel Time: 3.9 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 4443861.5, Avg: 4443861.6, Max: 4443861.6, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.9, Avg: 1.1, Max: 1.9, Diff: 0.9, Sum: 8.9]
      [Update RS (ms): Min: 0.3, Avg: 0.9, Max: 1.0, Diff: 0.7, Sum: 7.0]
         [Processed Buffers: Min: 31, Avg: 36.4, Max: 44, Diff: 13, Sum: 291]
      [Scan RS (ms): Min: 0.4, Avg: 0.4, Max: 0.4, Diff: 0.0, Sum: 3.2]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 1.1, Avg: 1.3, Max: 1.3, Diff: 0.2, Sum: 10.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.4, Max: 2, Diff: 1, Sum: 11]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]
      [GC Worker Total (ms): Min: 3.6, Avg: 3.7, Max: 3.8, Diff: 0.2, Sum: 29.9]
      [GC Worker End (ms): Min: 4443865.2, Avg: 4443865.3, Max: 4443865.4, Diff: 0.1]
   [Code Root Fixup: 0.2 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 1.5 ms]
      [Choose CSet: 0.1 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.3 ms]
   [Eden: 317.0M(317.0M)->0.0B(318.0M) Survivors: 16.0M->15.0M Heap: 921.2M(2224.0M)->516.7M(2224.0M)]
 [Times: user=0.04 sys=0.00, real=0.00 secs]

四个关键信息
新生代垃圾收集发生的时间——2016-12-12T10:40:18.811-0500，通过设置-XX:+PrintGCDateStamps参数可以打印出这个时间；
JVM启动后的相对时间——25.959
这次收集的类型——新生代收集，只回收Eden分区
这次收集花费的时间——0.0305171s，即30ms
列出了新生代收集中并行收集的详细过程
Parallel Time：并行收集任务在运行过程中引发的STW（Stop The World）时间，从新生代垃圾收集开始到最后一个任务结束，共花费26.6ms
GC Workers：有4个线程负责垃圾收集，通过参数-XX:ParallelGCThreads设置，这个参数的值的设置，跟CPU有关，如果物理CPU支持的线程个数小于8，则最多设置为8；如果物理CPU支持的线程个数大于8，则默认值为number * 5/8
GC Worker Start：第一个垃圾收集线程开始工作时JVM启动后经过的时间（min）；最后一个垃圾收集线程开始工作时JVM启动后经过的时间（max）；diff表示min和max之间的差值。理想情况下，你希望他们几乎是同时开始，即diff趋近于0。
Ext Root Scanning：扫描root集合（线程栈、JNI、全局变量、系统表等等）花费的时间，扫描root集合是垃圾收集的起点，尝试找到是否有root集合中的节点指向当前的收集集合（CSet）
Update RS(Remembered Set or RSet)：每个分区都有自己的RSet，用来记录其他分区指向当前分区的指针，如果RSet有更新，G1中会有一个post-write barrier管理跨分区的引用——新的被引用的card会被标记为dirty，并放入一个日志缓冲区，如果这个日志缓冲区满了会被加入到一个全局的缓冲区，在JVM运行的过程中还有线程在并发处理这个全局日志缓冲区的dirty card。Update RS表示允许垃圾收集线程处理本次垃圾收集开始前没有处理好的日志缓冲区，这可以确保当前分区的RSet是最新的。
Processed Buffers，这表示在Update RS这个过程中处理多少个日志缓冲区。
Scan RS：扫描每个新生代分区的RSet，找出有多少指向当前分区的引用来自CSet。
Code Root Scanning：扫描代码中的root节点（局部变量）花费的时间
Object Copy：在疏散暂停期间，所有在CSet中的分区必须被转移疏散，Object Copy就负责将当前分区中存活的对象拷贝到新的分区。
Termination：当一个垃圾收集线程完成任务时，它就会进入一个临界区，并尝试帮助其他垃圾线程完成任务（steal outstanding tasks），min表示该垃圾收集线程什么时候尝试terminatie，max表示该垃圾收集回收线程什么时候真正terminated。
Termination Attempts：如果一个垃圾收集线程成功盗取了其他线程的任务，那么它会再次盗取更多的任务或再次尝试terminate，每次重新terminate的时候，这个数值就会增加。
GC Worker Other：垃圾收集线程在完成其他任务的时间
GC Worker Total：展示每个垃圾收集线程的最小、最大、平均、差值和总共时间。
GC Worker End：min表示最早结束的垃圾收集线程结束时该JVM启动后的时间；max表示最晚结束的垃圾收集线程结束时该JVM启动后的时间。理想情况下，你希望它们快速结束，并且最好是同一时间结束。
列出了新生代GC中的一些任务：
Code Root Fixup ：释放用于管理并行垃圾收集活动的数据结构，应该接近于0，该步骤是线性执行的；
Code Root Purge：清理更多的数据结构，应该很快，耗时接近于0，也是线性执行。
Clear CT：清理card table
包含一些扩展功能
Choose CSet：选择要进行回收的分区放入CSet（G1选择的标准是垃圾最多的分区优先，也就是存活对象率最低的分区优先）
Ref Proc：处理Java中的各种引用——soft、weak、final、phantom、JNI等等。
Ref Enq：遍历所有的引用，将不能回收的放入pending列表
Redirty Card：在回收过程中被修改的card将会被重置为dirty
Humongous Register：JDK8u60提供了一个特性，巨型对象可以在新生代收集的时候被回收——通过G1ReclaimDeadHumongousObjectsAtYoungGC设置，默认为true。
Humongous Reclaim：做下列任务的时间：确保巨型对象可以被回收、释放该巨型对象所占的分区，重置分区类型，并将分区还到free列表，并且更新空闲空间大小。
Free CSet：将要释放的分区还回到free列表。
展示了不同代的大小变化，以及堆大小的自适应调整。
Eden:1097.0M(1097.0M)->0.0B(967.0M)：（1）当前新生代收集触发的原因是Eden空间满了，分配了1097M，使用了1097M；（2）所有的Eden分区都被疏散处理了，在新生代结束后Eden分区的使用大小成为了0.0B；（3）Eden分区的大小缩小为967.0M
Survivors:13.0M->139.0M：由于年轻代分区的回收处理，survivor的空间从13.0M涨到139.0M；
Heap:1694.4M(2048.0M)->736.3M(2048.0M)：（1）在本次垃圾收集活动开始的时候，堆空间整体使用量是1694.4M，堆空间的最大值是2048M；（2）在本次垃圾收集结束后，堆空间的使用量是763.4M，最大值保持不变。
第6点展示了本次新生代垃圾收集的时间
user=0.8：垃圾收集线程在新生代垃圾收集过程中消耗的CPU时间，这个时间跟垃圾收集线程的个数有关，可能会比real time大很多；
sys=0.0：内核态线程消耗的CPU时间
-real=0.03：本次垃圾收集真正消耗的时间；

 

2.924: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0130491 secs]
   [Parallel Time: 11.8 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 2923.8, Avg: 2924.3, Max: 2924.8, Diff: 1.0]
      [Ext Root Scanning (ms): Min: 0.8, Avg: 2.7, Max: 10.6, Diff: 9.8, Sum: 21.7]
      [Update RS (ms): Min: 0.0, Avg: 0.7, Max: 1.4, Diff: 1.4, Sum: 6.0]
         [Processed Buffers: Min: 0, Avg: 3.4, Max: 11, Diff: 11, Sum: 27]
      [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.1, Diff: 0.1, Sum: 0.1]
      [Object Copy (ms): Min: 0.0, Avg: 0.7, Max: 1.4, Diff: 1.3, Sum: 5.7]
      [Termination (ms): Min: 0.0, Avg: 6.9, Max: 7.9, Diff: 7.9, Sum: 55.1]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 10.6, Avg: 11.1, Max: 11.6, Diff: 1.0, Sum: 88.7]
      [GC Worker End (ms): Min: 2935.4, Avg: 2935.4, Max: 2935.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 1.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.6 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 3072.0K(3072.0K)->0.0B(2048.0K) Survivors: 2048.0K->1024.0K Heap: 25.0M(30.0M)->23.5M(30.0M)]
 [Times: user=0.10 sys=0.00, real=0.02 secs]
3.601: [GC concurrent-root-region-scan-start]
3.603: [GC concurrent-root-region-scan-end, 0.0021728 secs]
3.603: [GC concurrent-mark-start]
3.611: [GC concurrent-mark-end, 0.0077783 secs]
3.611: [GC remark 3.611: [Finalize Marking, 0.0011842 secs] 3.612: [GC ref-proc, 0.0001417 secs] 3.612: [Unloading, 0.0022275 secs], 0.0039083 secs]
 [Times: user=0.03 sys=0.00, real=0.00 secs]
3.615: [GC cleanup 29M->28M(2224M), 0.0013529 secs]
 [Times: user=0.00 sys=0.00, real=0.01 secs]
3.617: [GC concurrent-cleanup-start]
3.617: [GC concurrent-cleanup-end, 0.0000089 secs]

标志着并发垃圾收集阶段的开始：

GC pause(G1 Evacuation Pause)(young)(initial-mark)：为了充分利用STW的机会来trace所有可达（存活）的对象，
initial-mark阶段是作为新生代垃圾收集中的一部分存在的（搭便车）。
initial-mark设置了两个TAMS（top-at-mark-start）变量，用来区分存活的对象和在并发标记阶段新分配的对象。
在TAMS之前的所有对象，在当前周期内都会被视作存活的。表示第并发标记阶段做的第一个事情：根分区扫描

GC concurrent-root-region-scan-start：根分区扫描开始，根分区扫描主要扫描的是新的survivor分区，
找到这些分区内的对象指向当前分区的引用，如果发现有引用，则做个记录；
GC concurrent-root-region-scan-end：根分区扫描结束，耗时0.0030613s
表示并发标记阶段

GC Concurrent-mark-start：并发标记阶段开始。
（1）并发标记阶段的线程是跟应用线程一起运行的，不会STW，所以称为并发；并发标记阶段的垃圾收集线程，默认值是Parallel Thread个数的25%，
这个值也可以用参数-XX:ConcGCThreads设置；
（2）trace整个堆，并使用位图标记所有存活的对象，因为在top TAMS之前的对象是隐式存活的，
所以这里只需要标记出那些在top TAMS之后、阈值之前的；
（3）记录在并发标记阶段的变更，G1这里使用了SATB算法，该算法要求在垃圾收集开始的时候给堆做一个快照，
在垃圾收集过程中这个快照是不变的，
但实际上肯定有些对象的引用会发生变化，这时候G1使用了pre-write barrier记录这种变更，并将这个记录存放在一个SATB缓冲区中，
如果该缓冲区满了就会将它加入到一个全局的缓冲区，同时G1有一个线程在并行得处理这个全局缓冲区；
（4）在并发标记过程中，会记录每个分区的存活对象占整个分区的大小的比率；
GC Concurrent-mark-end：并发标记阶段结束，耗时0.3055438s
重新标记阶段，会Stop the World

Finalize Marking：Finalizer列表里的Finalizer对象处理，耗时0.0014099s；
GC ref-proc：引用（soft、weak、final、phantom、JNI等等）处理，耗时0.0000480s；
Unloading：类卸载，耗时0.0025840s；
除了前面这几个事情，这个阶段最关键的结果是：绘制出当前并发周期中整个堆的最后面貌，剩余的SATB缓冲区会在这里被处理，所有存活的对象都会被标记；
清理阶段，也会Stop the World

计算出最后存活的对象：标记出initial-mark阶段后分配的对象；标记出至少有一个存活对象的分区；
为下一个并发标记阶段做准备，previous和next位图会被清理；
没有存活对象的老年代分区和巨型对象分区会被释放和清理；
处理没有任何存活对象的分区的RSet；
所有的老年代分区会按照自己的存活率（存活对象占整个分区大小的比例）进行排序，为后面的CSet选择过程做准备；
并发清理阶段

GC concurrent-cleanup-start：并发清理阶段启动。完成第5步剩余的清理工作；
将完全清理好的分区加入到二级free列表，等待最终还会到总体的free列表；
GC concurrent-cleanup-end：并发清理阶段结束，耗时0.0012954s

35.277: [Full GC (Allocation Failure)  29M->23M(30M), 0.1271664 secs]
   [Eden: 0.0B(1024.0K)->0.0B(1024.0K) Survivors: 0.0B->0.0B Heap: 29.7M(30.0M)->23.9M(30.0M)], [Metaspace: 56318K->56251K(1099776K)]
 [Times: user=0.18 sys=0.00, real=0.13 secs]