java G1垃圾回收日志

境里婆娑 于 2020-04-25 18:52:32 发布

提起看GC日志大部分同学可能都会皱起眉头不知道如何看、什么时候看以及GC日志如何帮助我们调优JVM等。本篇文章将讲解主流垃圾回收器G1，目前Java官方推荐使用G1，所以学看G1垃圾回收日志迫在眉睫。

在学习查看G1 GC日志之前，如果对G1不是很了解，可以看这篇文章，讲的非常详细。

传送门： G1垃圾收集器简介

G1的日志参数分为等级递增的三块，这篇文章将会分别介绍每一部分参数的作用和调优时候使用的场景。

一、如何在idea打印G1日志

在idea中配置启动参数 VM options: -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseG1GC

二、G1基础参数

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

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

三、G1新生代收集

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

     1  2020-04-25T15:36:17.135+0800: [GC pause (G1 Evacuation Pause) (young), 0.0044414 secs]
     2     [Parallel Time: 3.4 ms, GC Workers: 4]
          [GC Worker Start (ms): Min: 8782.3, Avg: 8783.2, Max: 8785.7, Diff: 3.3]
          [Ext Root Scanning (ms): Min: 0.0, Avg: 0.4, Max: 0.6, Diff: 0.6, Sum: 1.6]
          [Update RS (ms): Min: 0.0, Avg: 1.0, Max: 1.5, Diff: 1.5, Sum: 4.1]
         [Processed Buffers: Min: 0, Avg: 2.5, Max: 6, Diff: 6, Sum: 10]
          [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.0, Diff: 0.0, Sum: 0.0]
          [Object Copy (ms): Min: 0.0, Avg: 1.0, Max: 1.3, Diff: 1.3, Sum: 3.9]
          [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
          [GC Worker Total (ms): Min: 0.0, Avg: 2.5, Max: 3.3, Diff: 3.3, Sum: 9.9]
          [GC Worker End (ms): Min: 8785.7, Avg: 8785.7, Max: 8785.7, Diff: 0.0]
    3  [Code Root Fixup: 0.0 ms]
       [Code Root Migration: 0.0 ms]
       [Clear CT: 0.0 ms]
    4   [Other: 1.0 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 0.6 ms]
          [Ref Enq: 0.0 ms]
          [Free CSet: 0.0 ms]
    5   [Eden: 4096.0K(4096.0K)->0.0B(3072.0K) Survivors: 1024.0K->1024.0K Heap: 23.9M(28.0M)->20.4M(28.0M)]
    6 [Times: user=0.00 sys=0.02, real=0.01 secs] 

1、 四个关键信息

• 新生代垃圾收集发生的时间——2020-04-25T15:36:17.135+0800，通过设置-XX:+PrintGCDateStamps参数可以打印出这个时间；
• 这次收集的类型——新生代收集，只回收Eden分区
• 这次收集花费的时间——0.0044414 secs，即4ms

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

• Parallel Time：并行收集任务在运行过程中引发的STW（Stop The World）时间，从新生代垃圾收集开始到最后一个任务结束，共花费3.4 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提供了一个特性，巨型对象可以在新生代收集的时候被回收——通过G1ReclaimDeadHumongousObjectsAtYoungGC设置，默认为true。
• Humongous Reclaim：做下列任务的时间：确保巨型对象可以被回收、释放该巨型对象所占的分区，重置分区类型，并将分区还到free列表，并且更新空闲空间大小。
• Free CSet：将要释放的分区还回到free列表。

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

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

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

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

四、并发垃圾收集

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

xxxxxxxxxx
1 2020-04-25T15:36:17.590+0800: [GC pause (G1 Evacuation Pause) (young),(initial-mark), 0.0043944 secs]
2 2020-04-25T15:36:17.590+0800: [GC concurrent-root-region-scan-start]
  2020-04-25T15:36:17.594+0800: [GC concurrent-root-region-scan-end, 0.0043944 secs]
3 2020-04-25T15:36:17.594+0800: [GC concurrent-mark-start]
  2020-04-25T15:36:17.640+0800: [GC concurrent-mark-end, 0.0460160 secs]
4 2020-04-25T15:36:17.640+0800: [GC remark [GC ref-proc, 0.0028598 secs], 0.0130111 secs]
 [Times: user=0.00 sys=0.00, real=0.01 secs] 
5 2020-04-25T15:36:17.654+0800: [GC cleanup 18M->18M(56M), 0.0001847 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
6 2020-04-25T15:36:17.890+0800: [GC concurent-cleanup-stat]
  2020-04-25T15:36:17.904+0800: [GC concurrent-cleanup-end, 0.0001847 secs]

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.0460160 secs

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.0460160 secs

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

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

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

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

6、并发清理阶段

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

五、程序发生Full GC

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

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

xxxxxxxxxx
2020-04-25T18:00:11.267+0800: [Full GC (Allocation Failure)  1520M->918M(1886M), 5.1284574 secs]
   [Eden: 0.0B(93.0M)->0.0B(94.0M) Survivors: 1024.0K->0.0B Heap: 1520.8M(1886.0M)->918.5M(1886.0M)], [Metaspace: 39714K->39714K(1085440K)]
 [Times: user=5.02 sys=0.00, real=5.13 secs] 
2020-04-25T18:00:16.395+0800: [Full GC (Allocation Failure)  918M->916M(1886M), 4.7699272 secs]
   [Eden: 0.0B(94.0M)->0.0B(94.0M) Survivors: 0.0B->0.0B Heap: 918.5M(1886.0M)->916.1M(1886.0M)], [Metaspace: 39714K->39488K(1085440K)]
 [Times: user=4.73 sys=0.00, real=4.77 secs] 

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

xxxxxxxxxx
1 2020-04-25T18:00:11.266+0800: Total time for which application threads were stopped: 0.0024315 seconds
2 2020-04-25T18:00:11.266+0800: Application time: 0.0000549 seconds

1 、记录了应用线程在安全点被暂停的总时间（也就是STW的总时间） 2、 记录了在两个安全点之间应用线程运行的时间

本篇文章参考：Collecting and reading G1 garbage collector logs - part 2