一次简单的G1GC参数调优

缘起

交易的查询服务调用组件的ES进行查询，ES服务会间歇性的3-4天抖动一次（发生mixedGC），每次mixedgc耗时都在700ms+，而正常的dubbo超时设置在1s左右，所以当发生GC的时候会引起短时集中式的查询超时，引起大量报警，而在之前的处理手段都是手动在凌晨四点触发GC，防止白天对业务应用产生抖动。

插曲

这里要纠正一个很多人的误解，为什么G1老年代的收集叫做mixedGC？
首先G1的进行老年代垃圾回收的时候不一定是全部的老年代，一般是部分的old region，然后因为老年的收集是可以和young gc同时进行的，所以叫mixedgc。

大部分我遇见以及协助排查的GC案例中几乎最终都是代码的问题，比较令人的满意的一个系统运行的场景其实是每次Ygc都能很好的消化掉垃圾对象，毕竟G1垃圾收集器的默认参数又少、又不错。

开始

（如上图）我们从一个正常来说服务调用的链路说起：
从链路追踪来看，上游应用发送请求的时间和下游开始处理请求的时间应该相差无几。但是，一个rpc过程抛开业务逻辑中间需要哪些过程呢？

（此图从网上copy，如有抄袭嫌疑，请联系我删除狗头保命）
可以看到，有序列化，网络传输等等。那一般接口超时会有哪些因素引起呢？
穷举法：网络问题、服务硬件问题、GC问题等

历史重现

X月XX日，线上查询服务又一次发生了抖动，于是公司内某张姓大佬过来问我,对话如下：
张大佬：鸡哥，请教个问题
鸡哥：你说说看，我应该不会（）
张大佬：G1中加了-XX:+ParallelRefProcEnabled参数之后，GC耗时还是会很长，导致一波超时，你知道什么情况么？
鸡哥：你确定么？

我们来分析下这个参数，按道理来说这个参数（-XX:+ParallelRefProcEnabled）的含义是：尽可能启用并行引用处理
那好，
我们探索下他为什么要加这个参数？是出现了什么现象让他要加这个参数？
原来是张姓大佬通过gclog发现每次GC的【ref proc】阶段耗时比较长，于是他从网上搜索到了这个参数之后就加上试了一下

现象

如上图我们可以发现在gc过程中 ref-proc（mixedgc）阶段发生了700ms+的暂停
那

【ref proc】阶段到底是干什么的？

其实是对各种软弱虚引用等的处理
图中ref-proc 0.7034259 secs 就是处理 soft、weak、phantom、final、JNI 等等引用的时间
Oracle官方文档如下描述：
其实是在G1的remark阶段，对上述的引用根据其特定类型更新所指对象

额外分析

这又得从G1的Ygc说起，我们都知道，Ygc就是对象填满Eden区然后触发Ygc，而正常来说G1中有设置

• -XX:MaxGCPauseMillis GC 最大停顿时间，默认 200ms 这个参数会影响到Ygc的STW时间，为什么呢？我们思考一下， MaxGCPauseMillis 时间越小，给STW时间也就越小，年轻代大概率就越小；反之 MaxGCPauseMillis 时间越大，给STW时间也就越大，年轻代大概率就会越大。此时是不是有人会有疑问？那我为了减少STW的时间，我就去降低MaxGCPauseMillis
  此言差矣！！！！
  MaxGCPauseMillis 越小，年轻代也越小，从而导致有很多短生命周期的对象被过早晋升到老年代。而老年代你们都懂的，标记清理过程比年轻代要复杂的多，整体效率也低，就导致虽然GC停滞时间下降了，但GC次数可能增多，整体吞吐量下降的情况。并且GC次数增多也会导致对CPU资源的占用增加，跟业务线程一起争抢CPU

第一次处理

然后当天晚点时间，我被拉进一个三人组成的GC问题处理群

实验了
三组对比参数

未调试:没有加ParallelRefProcEnabled，年轻代自动分配了17g，Ygc（40ms），mixedgc （500ms）
调试1:-XX:+ParallelRefProcEnabled，年轻代自动分配了2g，Ygc（50ms），Ygc次数增加，mixedgc（200ms）
调试2:-XX:+ParallelRefProcEnabled和-XX:ParallelgCThreads=8，年轻代17g，Ygc（40ms），Ygc次数与未调试的情况差不多，mixedgc还没有触发，所以耗时未知

我们可以基本上看到很明显的问题就是通过加入(-XX:+ParallelRefProcEnabled)
现象：

总结一

其实我们发现官网推荐的指导手段，让gc时间从700ms+下降到300ms左右，但是对于业务侧还是会引起一波超时抖动

第二次处理

当然300ms完全没办法支撑，还是会带来大量抖动，但是现有的gclog不够观察到本质，于是我推荐了如下参数，观测更具体的信息
-XX:+PrintReferenceGC

第二次现象

终于在X月X号，终于触发了一次Mixedgc，日志也出来了（如下）

第二次处理

我们可以看到Softreference和FinalReference 占了两个大头，一个是132ms，一个255ms
其实问题几乎就已经快压缩到最后了，此时可以看到Application stop 621ms

第三次现象

于是，问题定位到了就可以着手去解决了！
因为软引用大家都知道，内存不足的时候才会去收集，所以项目中生成的软引用对象太多的话，会在gc过程中产生较大的处理压力
我们这次加上了 -XX:SoftRefLRUPolicyMSPerMB=0

官方解释：Soft reference在虚拟机中比在客户集中存活的更长一些。其清除频率可以用命令行参数 -XX:SoftRefLRUPolicyMSPerMB=<N>来控制，这可以指定每兆堆空闲空间的 soft reference 保持存活（一旦它不强可达了）的毫秒数，这意味着每兆堆中的空闲空间中的 soft reference 会（在最后一个强引用被回收之后）存活1秒钟。注意，这是一个近似的值，因为 soft reference 只会在垃圾回收时才会被清除，而垃圾回收并不总在发生。系统默认为一秒，我觉得没必要等1秒，客户集中不用就立刻清除，改为 -XX:SoftRefLRUPolicyMSPerMB=0；

第三次结果

结果是什么？

我们可以看到的现象是 soft引用和final引用在每次Ygc过程中都被收集掉一部分，且数量比之前大一倍
而finalReference的疑问是什么呢？
因为在java8的SocketServiceImpl里实现了Object的finalize方法，为了防止socket链接忘了释放资源，而进行帮助释放

当有大量短链接未来得及释放，会导致Finalizer对象过多，引起一开始我们看到的现象，所以猜测ES使用的OKHTTP的调用方式，但是无法dump，所以无从考证
但因为已经在每次Ygc中进行收集了，其实也算是达到预期，但是不是很完美。
当然好像JDK9中的AbstractPlainSocketImpl已经不再复写finalize方法了，因为finallize() 方法是Object类的方法, 用于在类被GC回收时 做一些处理操作, 但是JVM并不能保证finalize() 方法一定被执行,由finalize()方法的调用时机具有不确定性，从一个对象变得不可到达开始，到finalize()方法被执行，所花费的时间这段时间是任意长的。我们并不能依赖finalize()方法能及时的回收占用的资源，可能出现的情况是在我们耗尽资源之前，gc却仍未触发，因而通常的做法是提供显示的close()方法供客户端手动调用

小插曲

不少人的认知是soft引用会在内存不足时候回收？其实不一定，软引用的回收是需要一定条件的我们看官方文档怎么说

clock - timestamp <= freespace * SoftRefLRUPolicyMSPerMB
clock：上次GC的时间戳
timestamp：表示最近一次读取软引用对象的时间戳
这两者的差值表示该软引用对象多久没被使用了，差值越大，软引用对象价值越低，负数则表示软引用对象刚刚被使用
freespace是空闲空间大小，SoftRefLRUPolicyMSPerMB表示每一MB的空闲内存空间可以允许软引用对象存活多久，这也就间接的解释了，为什么空间不够用，空闲空间越小，软应用对象就会被回收，因为它的存活时间会随着空闲空间的减小而递减。可以把 【freespace * SoftRefLRUPolicyMSPerMB】理解为忍耐度，对软应用对象的忍耐程度。

等待

其实从gclog和现象之中大概已经猜测到基本上已经算是成功了，但是呢，加上这个参数【SoftRefLRUPolicyMSPerMB】也是有风险的，如下我说的
例子：假设程序中有很多反射创建类的操作，因为反射创建的类本身的Class对象都是被SoftReference软引用的，加上了如上的参数，软引用就会被尽快的释放掉，所以就会产生，反射创建大量类->刚创建完GC回收掉很多->反射执行继续创建大量类，最终导致Metaspace区域被打满->导致FullGC

结果

等待了4天之后，听着张姓大佬一阵激动的叫喊

发现mixedgc已经稳定到85ms左右

小插曲

1.为什么软引用收集参数【SoftRefLRUPolicyMSPerMB】没有在jvm中默认打开？
答：因为软引用的特性特别适合做Cache，设计者目的就是想让cache常驻内存，所以要到内存不够的时候才去触发收集

2.是否要引用ZGC？
中间有人给张姓大佬推荐了ZGC,于是我掏出了这种图，JDK11开始有的，也是2018年9月左右发布，
第一，可以尝试，但是这算是屏蔽了问题，而走捷径；
第二，没有人完全能hold住，出了问题谁来负责和修复？

GC调优的几个核心要素

一.要有信心

二.不断压缩问题到死角

三.多组参数实验对比

毕竟没有兼容所有场景的参数，只有符合自己业务场景的参数调优

附件（给大家参考借鉴，gclog中每个步骤在干什么）：

[GC pause (G1 Evacuation Pause) (young), 0.0022483 secs]
young -> 年轻代 Evacuation-> 复制存活对象 
[Parallel Time: 1.0 ms, GC Workers: 10] # 并发执行的GC线程数，以下阶段是并发执行的
[GC Worker Start (ms): Min: 109.0, Avg: 109.1, Max: 109.1, Diff: 0.2] 
[Ext Root Scanning (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 2.3] # 外部根分区扫描
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] # 更新已记忆集合 Update RSet，检测从年轻代指向老年代的对象
[Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] 
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]# RSet扫描
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] # 代码根扫描
[Object Copy (ms): Min: 0.3, Avg: 0.3, Max: 0.4, Diff: 0.1, Sum: 3.5] # 转移和回收，拷贝存活的对象到survivor/old区域
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] # 完成上述任务后，如果任务队列已空，则工作线程会发起终止要求。
[Termination Attempts: Min: 1, Avg: 5.8, Max: 9, Diff: 8, Sum: 58]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] # GC外部的并行活动，该部分并非GC的活动，而是JVM的活动导致占用了GC暂停时间(例如JNI编译)。
[GC Worker Total (ms): Min: 0.5, Avg: 0.6, Max: 0.7, Diff: 0.2, Sum: 5.9]
[GC Worker End (ms): Min: 109.7, Avg: 109.7, Max: 109.7, Diff: 0.0]
[Code Root Fixup: 0.0 ms] # 串行任务，根据转移对象更新代码根
[Code Root Purge: 0.0 ms] #串行任务， 代码根清理
[Clear CT: 0.5 ms] #串行任务，清除全局卡片 Card Table 标记
[Other: 0.8 ms]
[Choose CSet: 0.0 ms] # 选择下次收集集合 CSet
[Ref Proc: 0.4 ms] # 引用处理 Ref Proc，处理软引用、弱引用、虚引用、final引用、JNI引用
[Ref Enq: 0.0 ms] # 引用排队 Ref Enq
[Redirty Cards: 0.3 ms] # 卡片重新脏化 Redirty Cards：重新脏化卡片
[Humongous Register: 0.0 ms] 
[Humongous Reclaim: 0.0 ms] # 回收空闲巨型分区 Humongous Reclaim，通过查看所有根对象以及年轻代分区的RSet，如果确定RSet中巨型对象没有任何引用，该对象分区会被回收。
[Free CSet: 0.0 ms] # 释放分区 Free CSet
[Eden: 12288.0K(12288.0K)->0.0B(11264.0K) Survivors: 0.0B->1024.0K Heap: 12288.0K(20480.0K)->832.0K(20480.0K)]
[Times: user=0.01 sys=0.00, real=0.00 secs]
从年轻代分区拷贝存活对象时，无法找到可用的空闲分区
从老年代分区转移存活对象时，无法找到可用的空闲分区 这两种情况之一导致的 YGC
[GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0916534 secs]
并发标记周期 Concurrent Marking Cycle 中的 根分区扫描阶段，被 YGC中断
[GC pause (G1 Evacuation Pause) (young)[GC concurrent-root-region-scan-end, 0.0007157 secs]