【G1】并发收集日志分析 - shenjy24/jackal-gc GitHub Wiki

日志输出

[GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.1197553 secs]
   [Parallel Time: 118.3 ms, GC Workers: 15]
      [GC Worker Start (ms): Min: 4787.2, Avg: 4787.4, Max: 4787.7, Diff: 0.5]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.4, Max: 0.6, Diff: 0.6, Sum: 6.1]
      [Update RS (ms): Min: 0.0, Avg: 0.4, Max: 1.2, Diff: 1.2, Sum: 5.4]
         [Processed Buffers: Min: 0, Avg: 1.1, Max: 2, Diff: 2, Sum: 16]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.9]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 116.1, Avg: 116.8, Max: 117.2, Diff: 1.1, Sum: 1752.4]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 3.2]
         [Termination Attempts: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 17]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.6]
      [GC Worker Total (ms): Min: 117.7, Avg: 117.9, Max: 118.2, Diff: 0.5, Sum: 1768.6]
      [GC Worker End (ms): Min: 4905.3, Avg: 4905.3, Max: 4905.4, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.5 ms]
   [Other: 1.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.4 ms]
   [Eden: 3664.0M(3664.0M)->0.0B(3560.0M) Survivors: 436.0M->516.0M Heap: 11.6G(15.9G)->9307.1M(15.9G)]
 [Times: user=1.25 sys=0.39, real=0.12 secs] 
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0001724 secs]
[GC concurrent-mark-start]
[GC concurrent-mark-end, 0.0203914 secs]
[GC remark [Finalize Marking, 0.0001128 secs] [GC ref-proc, 0.0000842 secs] [Unloading, 0.0003881 secs], 0.0030559 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC cleanup 9450M->9090M(15G), 0.0014168 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC concurrent-cleanup-start]
[GC concurrent-cleanup-end, 0.0001432 secs]
  1. 标志着并发垃圾收集阶段的开始 (初始标记)：

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

  1. 表示并发标记阶段做的第一个事情：根分区扫描
  • GC concurrent-root-region-scan-start：根分区扫描开始，根分区扫描主要扫描的是新的survivor分区，找到这些分区内的对象指向当前分区的引用，如果发现有引用，则做个记录；
  • GC concurrent-root-region-scan-end：根分区扫描结束，耗时0.0001724s。
  1. 表示并发标记阶段
  • 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.0203914s。
  1. 重新标记阶段，会Stop the World
  • Finalize Marking：Finalizer列表里的Finalizer对象处理，耗时0.0001128s；
  • GC ref-proc：引用（soft、weak、final、phantom、JNI等等）处理，耗时0.0000842s；
  • Unloading：类卸载，耗时0.0003881s；
  • 除了前面这几个事情，这个阶段最关键的结果是：绘制出当前并发周期中整个堆的最后面貌，剩余的SATB缓冲区会在这里被处理，所有存活的对象都会被标记；
  1. 清理阶段，也会Stop the World
  • 计算出最后存活的对象：标记出initial-mark阶段后分配的对象；标记出至少有一个存活对象的分区；
  • 为下一个并发标记阶段做准备，previous和next位图会被清理；
  • 没有存活对象的老年代分区和巨型对象分区会被释放和清理；
  • 处理没有任何存活对象的分区的RSet；
  • 所有的老年代分区会按照自己的存活率（存活对象占整个分区大小的比例）进行排序，为后面的CSet选择过程做准备；
  1. 并发清理阶段
  • GC concurrent-cleanup-start：并发清理阶段启动。完成第5步剩余的清理工作；将完全清理好的分区加入到二级free列表，等待最终还会到总体的free列表；
  • GC concurrent-cleanup-end：并发清理阶段结束，耗时0.0001432s

参考资料

深入理解G1的GC日志