g1垃圾收集器gc的四种日志解释

• 本文来源于：https://www.cnblogs.com/javaadu/p/11220234.html
• 本文翻译自：https://www.redhat.com/en/blog/collecting-and-reading-g1-garbage-collector-logs-part-2?source=author&term=22991

这篇文章将深入研究G1的日志和调优参数。为了在实际工作中对G1进行调优，作为开发者的你需要理解G1垃圾收集器的每个步骤，以及每个步骤在整个垃圾收集周期中的作用。为了方便读者学习，这篇文章将G1的日志参数分为等级递增的三块，这篇文章将会分别介绍每一部分参数的作用和调优时候使用的场景。

• 1、基础参数 ：在生产中使用G1收集器，必须使用这些参数
• 2、高级参数 ： 随着应用的成熟或业务负载的增加，需要使用这些参数针对某些问题进行调优。
• 3、Debug参数 ：这些参数是用来解决特定的性能问题，如果某个问题在非生产环境中无法复现，才会在生产环境中使用这些参数排查问题。

基础参数

如果你要在生产环境中使用G1 GC，下面这些跟日志相关的参数是必备的，有了这些参数，你才能排查基本的垃圾回收问题。

使用==-XX:GCLogFileSize设置合适的GC日志文件大小，使用-XX:NumberOfGCLogFiles设置要保留的GC日志文件个数，使用-Xloggc:/path/to/gc.log==设置GC日志文件的位置，通过上面三个参数保留应用在运行过程中的GC日志信息，我建议最少保留一个星期的GC日志，这样应用的运行时信息足够多的，方便排查问题。

新生代收集

和其他垃圾收集器一样，G1也使用==-XX:PrintGCDetails==打印出详细的垃圾收集日志，下面这张图是新生代收集的标准流程，我在这里将它分成了6个步骤：

1、2020-06-22T08:20:27.622+0000: 6372.924: [GC pause (G1 Evacuation Pause) (young), 0.0905509 secs]

2、 [Parallel Time: 79.6 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 6372924.2, Avg: 6372924.3, Max: 6372924.3, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 1.6, Avg: 3.5, Max: 8.1, Diff: 6.5, Sum: 14.0]
      [Update RS (ms): Min: 0.0, Avg: 0.9, Max: 1.3, Diff: 1.3, Sum: 3.6]
         [Processed Buffers: Min: 0, Avg: 6.0, Max: 14, Diff: 14, Sum: 24]
      [Scan RS (ms): Min: 1.3, Avg: 1.5, Max: 2.0, Diff: 0.7, Sum: 6.1]
      [Code Root Scanning (ms): Min: 3.5, Avg: 4.4, Max: 6.2, Diff: 2.7, Sum: 17.8]
      [Object Copy (ms): Min: 66.4, Avg: 69.0, Max: 71.0, Diff: 4.6, Sum: 275.9]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [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.1, Diff: 0.1, Sum: 0.4]
      [GC Worker Total (ms): Min: 79.3, Avg: 79.4, Max: 79.5, Diff: 0.2, Sum: 317.6]
      [GC Worker End (ms): Min: 6373003.6, Avg: 6373003.7, Max: 6373003.7, Diff: 0.1]
3、[Code Root Fixup: 0.4 ms]
   [Code Root Purge: 0.3 ms]
   [String Dedup Fixup: 3.2 ms, GC Workers: 4]
      [Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Table Fixup (ms): Min: 2.8, Avg: 3.0, Max: 3.1, Diff: 0.3, Sum: 11.9]
   [Clear CT: 0.8 ms]
4、[Other: 6.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 3.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 2.2 ms]
5、 [Eden: 2337.0M(2337.0M)->0.0B(2389.0M) Survivors: 120.0M->68.0M Heap: 2463.0M(4096.0M)->81.8M(4096.0M)]
6、[Times: user=0.34 sys=0.00, real=0.09 secs] 

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32

1、四个关键信息

• 新生代垃圾收集发生的时间——2020-06-22T08:20:27.622+0000，通过设置-XX:+PrintGCDateStamps参数可以打印出这个时间；
• JVM启动后的相对时间——6372.924
• 这次收集的类型——新生代收集，只回收Eden分区
• 这次收集花费的时间——0.0905509 secs，即90ms

2、列出了新生代收集中并行收集的详细过程

• Parallel Time：并行收集任务在运行过程中引发的STW（Stop The World）时间，从新生代垃圾收集开始到最后一个任务结束，共花费79.6 ms
• 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启动后的时间。理想情况下，你希望它们快速结束，并且最好是同一时间结束。

3、列出了新生代GC中的一些任务：

• ** Code Root Fixup ：** 释放用于管理并行垃圾收集活动的数据结构，应该接近于0，该步骤是线性执行的；
• Code Root Purge： 清理更多的数据结构，应该很快，耗时接近于0，也是线性执行。
• Clear CT： 清理card table

4、包含一些扩展功能

• Choose CSet： 选择要进行回收的分区放入CSet（G1选择的标准是垃圾最多的分区优先，也就是存活对象率最低的分区优先）
• Ref Proc： 处理Java中的各种引用——soft、weak、final、phantom、JNI等等。
• Ref Enq： 遍历所有的引用，将不能回收的放入pending列表
• Redirty Card： 在回收过程中被修改的card将会被重置为dirty
• • Humongous Register： JDK8u60提供了一个特性，巨型对象可以在新生代收集的时候被回收——通过G1ReclaimDeadHumongousObje**ctsAtYoungGC ** 设置，默认为true。
• Humongous Reclaim： 做下列任务的时间：确保巨型对象可以被回收、释放该巨型对象所占的分区，重置分区类型，并将分区还到free列表，并且更新空闲空间大小。
• Free CSet： 将要释放的分区还回到free列表。

5、展示了不同代的大小变化，以及堆大小的自适应调整。

• Eden: 2337.0M(2337.0M)->0.0B(2389.0M)： （1）当前新生代收集触发的原因是Eden空间满了，分配了2337M，使用了2337M；（2）所有的Eden分区都被疏散处理了，在新生代结束后Eden分区的使用大小成为了0.0B；（3）Eden分区的大小缩小为2389.0M
• Survivors: 120.0M->68.0M： 由于年轻代分区的回收处理，survivor的空间从120.0M降到68.0M；
• Heap: 2463.0M(4096.0M)->81.8M(4096.0M)：（1）在本次垃圾收集活动开始的时候，堆空间整体使用量是2463.0M，堆空间的最大值是4096.0M；（2）在本次垃圾收集结束后，堆空间的使用量是81.8M，最大值保持不变。

第6点展示了本次新生代垃圾收集的时间

• user=0.34： 垃圾收集线程在新生代垃圾收集过程中消耗的CPU时间，这个时间跟垃圾收集线程的个数有关，可能会比real time大很多；
• sys=0.00： 内核态线程消耗的CPU时间
• real=0.09 secs： 本次垃圾收集真正消耗的时间；

并发垃圾收集

G1的第二种收集活动是并发垃圾收集，并发垃圾收集的触发条件有很多，但是做的工作都相同，它的日志如下所示：

1、2020-06-19T12:02:00.008+0000: 4482.342: [GC pause (G1 Evacuation Pause) (young) (initial-mark) (to-space exhausted), 0.1400888 secs]

2、 2020-06-19T12:02:00.148+0000: 4482.482: [GC concurrent-root-region-scan-start]
    2020-06-19T12:02:00.148+0000: 4482.482: [GC concurrent-root-region-scan-end, 0.0000847 secs]
3、 2020-06-19T12:02:00.148+0000: 4482.482: [GC concurrent-mark-start]
    2020-06-19T12:02:00.279+0000: 4482.613: [GC concurrent-mark-end, 0.1311217 secs]
4、 2020-06-19T12:02:00.280+0000: 4482.614: [GC remark 
            2020-06-19T12:02:00.280+0000: 4482.614: [Finalize Marking, 0.0002808 secs] 
            2020-06-19T12:02:00.280+0000: 4482.614: [GC ref-proc, 0.0196855 secs]
            2020-06-19T12:02:00.300+0000: 4482.634: [Unloading, 0.0296982 secs], 0.0531480 secs]
            [Times: user=0.14 sys=0.01, real=0.05 secs]      
5、 2020-06-19T23:20:00.589+0000: 45162.923: [GC cleanup 2758M->2628M(4096M), 0.0045787 secs]
            [Times: user=0.02 sys=0.00, real=0.00 secs]  

6、 2020-06-19T23:20:00.593+0000: 45162.928: [GC concurrent-cleanup-start]
    2020-06-19T23:20:00.594+0000: 45162.928: [GC concurrent-cleanup-end, 0.0002474 secs]
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

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

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

2、表示第并发标记阶段做的第一个事情：根分区扫描

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

3、表示并发标记阶段

• 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

4、重新标记阶段，会Stop the World

Finalize Marking： Finalizer列表里的Finalizer对象处理，耗时0.0014099s；

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

5、清理阶段，也会Stop the World

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

6、并发清理阶段

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

混合收集

在并发收集阶段结束后，你会看到混合收集阶段的日志，如下图所示，该日志的大部分跟之前讨论的新生代收集相同，只有第1部分不一样：GC pause (G1 Evacuation Pause) (mixed) (to-space exhausted), 0.0641103 secs，这一行表示这是一个混合垃圾收集周期；在混合垃圾收集处理的CSet不仅包括新生代的分区，还包括老年代分区——也就是并发标记阶段标记出来的那些老年代分区。

1、2020-06-19T12:36:00.123+0000: 6522.458: [GC pause (G1 Evacuation Pause) (mixed) (to-space exhausted), 0.0641103 secs]
2、 [Parallel Time: 12.6 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 6522458.3, Avg: 6522458.4, Max: 6522458.4, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 1.6, Avg: 1.8, Max: 2.2, Diff: 0.7, Sum: 7.2]
      [Update RS (ms): Min: 1.6, Avg: 2.4, Max: 2.8, Diff: 1.1, Sum: 9.5]
         [Processed Buffers: Min: 15, Avg: 21.5, Max: 27, Diff: 12, Sum: 86]
      [Scan RS (ms): Min: 0.4, Avg: 0.5, Max: 0.5, Diff: 0.2, Sum: 1.9]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.2]
      [Object Copy (ms): Min: 7.2, Avg: 7.8, Max: 8.4, Diff: 1.2, Sum: 31.1]
      [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: 12.5, Avg: 12.5, Max: 12.5, Diff: 0.0, Sum: 50.1]
      [GC Worker End (ms): Min: 6522470.9, Avg: 6522470.9, Max: 6522470.9, Diff: 0.0]
3、[Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [String Dedup Fixup: 1.6 ms, GC Workers: 4]
      [Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Table Fixup (ms): Min: 0.0, Avg: 1.1, Max: 1.5, Diff: 1.5, Sum: 4.3]
   [Clear CT: 0.2 ms]
4、[Other: 49.6 ms]
      [Evacuation Failure: 48.3 ms]
      [Choose CSet: 0.3 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.3 ms]
5、  [Eden: 157.0M(4096.0M)->0.0B(4096.0M) Survivors: 0.0B->0.0B Heap: 4093.4M(4096.0M)->4023.4M(4096.0M)]
6、[Times: user=0.21 sys=0.00, real=0.07 secs] 
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31

Full GC

如果堆内存空间不足以分配新的对象，或者是Metasapce空间使用率达到了设定的阈值，那么就会触发Full GC——你在使用G1的时候应该尽量避免这种情况发生，因为G1的Full Gc是单线程、会Stop The World，代价非常高。Full GC的日志如下图所示，从中你可以看出三类信息

• 1、Full GC的原因，这个图里是Allocation Failure，还有一个常见的原因是Metadata GC Threshold；
• 2、Full GC发生的频率，每隔几天发生一次Full GC还可以接受，但是每隔1小时发生一次Full GC则不可接受；
• 3、Full GC的耗时，这张图里的Full GC耗时150ms（PS：按照我的经验，实际运行中如果发生Full GC，耗时会比这个多很多）

1、2020-06-19T10:47:33.227+0000: 15.561: [Full GC (Allocation Failure)  4096M->96M(4096M), 0.3302938 secs]
   [Eden: 0.0B(4096.0M)->0.0B(4096.0M) Survivors: 0.0B->0.0B Heap: 4096.0M(4096.0M)->96.0M(4096.0M)], [Metaspace: 40813K->40629K(1085440K)]
 [Times: user=0.38 sys=0.03, real=0.33 secs] 
1
2
3

基础配置参数中，我这里还想介绍两个：-XX:+PrintGCApplicationStoppedTime和==-XX:+PrintGCApplicationConcurrentTime==，这两个参数也可以为你提供有用的信息，如下图所示：

2020-06-22T06:34:20.256+0000: 5.558:
1、Total time for which application threads were stopped: 0.0001350 seconds

2、Stopping threads took: 0.0000373 seconds
1
2
3
4

• 1、记录了应用线程在安全点被暂停的总时间（也就是STW的总时间）
• 2、记录了让所有应用线程进入安全点所花费的总时间