Elasticsearch GC 优化实战

近期业务查询线上ES集群出现频繁超时告警,尤其是早晨某个时间点固定的报一波超时,从调用链监控上很难看出是什么业务行为导致的。

初步猜测

查看Grafana上Elasticsaerch的基础监控,发现业务告警与ES的Old GC(老年代GC)卡顿时间基本吻合:

同时注意到,Old区的内存持续增长,不到1小时就会将Old区填满,经过Old GC几乎全部可以回收掉:

猜测:

  • 是什么导致Old区快速增长?可能是内存分配速率过高导致过早晋升?可能是分配很大的对象?
  • 为什么Old GC这么慢?ES卡顿大概率与它有关,早晨时间固定发生可能与业务某种行为有关。

因此决定申请线上权限去看一下ES的GC表现情况。

查看GC配置

因为线上ES没有开启GC日志,所以先用JVM工具从外围查看一下GC配置与大概情况。

jmap查看ES堆情况:

  • MaxHeapSize:整个堆31GB。
  • MaxNewSize:Young区只有1GB。
  • OldSize:Old区有30GB。
  • NewRatio:取值2表示Young区应该占整个堆的1/3,应该是10GB才对,而实际才1GB,这非常奇怪。

我们期望的默认行为是Young=10GB,Old=20GB才对,为什么变成了1GB和30GB这样?

查看了一下JVM最终的启动参数,竟然真的自行推断Young区只占1GB空间,难道是JVM的BUG?

把剩余的GC参数谷歌了一下,果然发现有人测试过JDK8的-XX:+UseConcMarkSweepGC会导致NewRatio参数失效,原因不明!

这么小的Young区肯定会导致频繁Young GC(通过jstat -gc观察YGC每秒1~2次),对ES性能肯定没有好处,虽然和Old GC慢没啥直接关系,但也必须先修复一下再说了,通过-Xmn直接指定Young区10GB即可:

重启ES观察到Young区大小正确,观察jstat -gc发现Young GC频率显著下降了6倍。

再次观察grafana,发现YGC频率的确下降(YGC之间有间隔了):

Old区仍旧保持高增速:

但是因为Young区从1GB调到10GB了,所以每次YGC对JVM heap的收缩振幅会更明显,图形上出现明显的起落,但整个JVM heap持续走高的势头没有改变,因为对象仍旧在快速晋升到Old区,直到Old区填满后一次Old GC再大幅回落。

开启GC日志

接下来要分析Old区快速增长的原因,另外要看一下为什么Old GC会卡顿1秒,能否优化?

配置开启GC日志,重启ES:

为了判断是不是存在很多”中生命期”的对象存在而导致频繁晋升到Old区,所以需要打开-XX:MaxTenuringThreshold=15参数,令Young区晋升条件提高为15代YGC,以便观察Young区的对象年龄分布。

一开始我采用默认参数是6代晋升,这是当时的截图:

图中观察到1~6岁的对象都有,每一代就几十MB的空间占用,我们知道YGC后6岁的就会进入Old区,1~5岁的就会都涨1岁,所以我怀疑就是每次YGC会导致第6代几十MB的”中生命期”对象晋升到Old区,大概算了一下这个速度的确和Old GC的周期接近,看样大概率是这个原因导致Old区增长的。

如果我调高晋升年龄到15代,有可能活到10岁的”中生命期”对象就会最终在YGC被回收掉,可能会减缓Old区的增长速度,抱着这个想法我才将XX:MaxTenuringThreshold调到了15,想给”中生命期”对象多一些机会被YGC回收掉。

但实际情况是15代都均匀的分布着对象,可见”中生命期”的对象活的比想象的要久,能熬过15代YGC还不释放,既然现实情况就是有很多”中生命期”对象存在,那减缓Old区增长的想法是比较难实现了,索性继续研究一下为什么Old GC那么卡的问题吧

优化Old GC速度

根据打印到磁盘上gc日志,可以深入分析一下CMS Old GC的流程耗时在哪里,我们应该重点关注会导致STW(stop the world)的阶段耗时。

CMS垃圾回收算法是Old区的GC算法,它的开始以这样的日志标识:

2021-03-12T13:19:54.273+0800: 96253.129: [GC (CMS Initial Mark) [1 CMS-initial-mark: 23554181K(31398336K)] 23611096K(32395136K), 0.0063801 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

初始化标记阶段,只会STW一丢丢的时间,基本可以忽略。

整个CMS的经历如下阶段:

在Remark阶段会有明显的STW,知乎上是这样描述的:

因为Old GC全流程比较漫长,期间Young区会快速填充,等到Remark阶段要扫全堆的时候Young区也填满了很多对象,此时强制配置一波YGC(本身又很快),应该可以减少Remark的STW耗时。

目前观察到Remark阶段耗时:

STW长达0.8秒,的确很惨,我们加上这个选项:

-XX:+CMSScavengeBeforeRemark

添加上述配置后,可以看到Remark阶段时间STW耗时缩短了7倍左右:

优化效果

红色为原线上配置的对照实例,其他机器均已生效新配置:

可见,GC频率与耗时均明显下降,新的Old GC耗时已经降低到原先的Young GC耗时的水平,早晨超时报警的情况也消失了。

 

如果文章帮助您解决了工作难题,您可以帮我点击屏幕上的任意广告,或者赞助少量费用来支持我的持续创作,谢谢~