缘起
交易的查询服务调用组件的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=
第三次结果
结果是什么?
我们可以看到的现象是 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左右
小插曲
为什么软引用收集参数【SoftRefLRUPolicyMSPerMB】没有在jvm中默认打开?
答:因为软引用的特性特别适合做Cache,设计者目的就是想让cache常驻内存,所以要到内存不够的时候才去触发收集
是否要引用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]