【译】深刻理解G1的GC日志（一）

本文翻译自： 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. 四个关键信息

   • 新生代垃圾收集发生的时间——2016-12-12T10:40:18.811-0500，经过设置-XX:+PrintGCDateStamps参数能够打印出这个时间；
   • JVM启动后的相对时间——25.959
   • 此次收集的类型——新生代收集，只回收Eden分区
   • 此次收集花费的时间——0.0305171s，即30ms

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

   • 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启动后的时间。理想状况下，你但愿它们快速结束，而且最好是同一时间结束。

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: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. 第6点展现了本次新生代垃圾收集的时间

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

并发垃圾收集

G1的第二种收集活动是并发垃圾收集，并发垃圾收集的触发条件有不少，可是作的工做都相同，它的日志以下图所示：

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),0.0129474s，这一行表示这是一个混合垃圾收集周期；在混合垃圾收集处理的CSet不只包括新生代的分区，还包括老年代分区——也就是并发标记阶段标记出来的那些老年代分区。

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，耗时会比这个多不少）

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

1. 记录了应用线程在安全点被暂停的总时间（也就是STW的总时间）
2. 记录了让全部应用线程进入安全点所花费的总时间
3. 记录了在两个安全点之间应用线程运行的时间

总结

这篇文章只是翻译了原文的第一部分，基础参数篇，我接下来会有一篇或两篇文章完成原文的高级参数和Debug参数两部分。------

本号专一于后端技术、JVM问题排查和优化、Java面试题、我的成长和自我管理等主题，为读者提供一线开发者的工做和成长经验，期待你能在这里有所收获。