JVM内存优化分享

2022-09-07 17:20:37 浏览数 (2)

JVM进程运行期间,可能会出现因为YGC或OGC周期过长导致的明显停顿,从而极大影响用户使用体验。本文总结了作者在一次针对JVM进程的整体调优过程中所使用的工具和方法,用于备忘。文中所述的系统为国内某知名2B公司自研的搜索引擎(类Elasticsearch),出于商业道德,作者未暴露任何代码,并对关键信息均予以更改和遮掩。

场景&&症状

系统:分布式搜索系统Skyper(化名)

场景:读写混合(单节点200并发)

症状:不定期JVM内存爆满卡死,YGC周期波动明显,单次YGC出现1s 的情况,严重影响使用体验

阶段1:Shard泄露寻因

怀疑:Shard对象泄露

怀疑理由:删除表格后,JVM内存消耗无变化。

背景介绍:Shard对象是Skyper数据库分片在内存中数据结构,其保存了表的元数据,状态数据,文件引用和查询上下文等数据,是Skyper单机的核心数据结构。正常情况下,表格创建的时候,JVM生成Shard对象,表格被删除的时候,Shard对象相应地被删除。

验证方法:JProfile 比较删表前后的内存快照

单机测试删表前Shard对象数量:5个单机测试删表前Shard对象数量:5个
删表后可见Shard对象仍然是5个删表后可见Shard对象仍然是5个

可见Shard对象缺失存在泄露,下一步:使用Jprofile 对残留的引用关系绘制graph

Shard对象在表格被删除后仍被引用Shard对象在表格被删除后仍被引用

如上图可见,在表格删除之后,JNI指针仍在引用JVM内存中的Shard对象,导致Shard一直无法被GC掉,到此问题1的root cause已经找到。

阶段2:查询上下文泄露寻因

问题:在Shard泄露问题解决之后,系统仍然在运行过程中表现出内存逐渐累积直至爆满的情况

怀疑:查询Context泄露

怀疑理由:随着查询并发的增加,内存累计迅速上升。

背景补充:所谓查询Context,是在一次‘查询过程中’保存相关数据的数据结构,例如from,size, lastDoc等。正常情况下,当一次查询结束之后,相应的查询Context不再被引用,就会脱链被回收,使得JVM内存保持在一个正常水平。

做法:单机测试大查询场景,检验JVM内存快照。

单机测试的JVM快照单机测试的JVM快照

如上图所示,在单机单线程查询2w次测试,仅1分钟后,内存中残留近15w个Context对象。对起out ref 进行merge分析后可见

起始终持有了大量元数据和lucene对象的引用,导致大量对象堆积。

fetch-clear只发给了命中的shardfetch-clear只发给了命中的shard

原因分析:在排序查询的场景下, 查询目标表格的所有shard上都会新建Context。但是在Query-Then-Fetch的流程中原系统‘符合Fetch条件的’的shard发送了clear request。这就导致了如上图所示,对于不符合fetch要求的shard2和shard3,其上的Context实际上并没有被释放掉。这一bug在查询size较小,而shard很多的情况造成的影响格外明显。例如,对于100个shard的表格,如果fetch阶段只有3个shard符合条件,则泄露的比例就高达97%。这在高并发查询的场景下,无疑将会造成JVM内存使用的灾难。

阶段3:Finalize异常

症状:在经过阶段1、2之后,Skyper已经能够平稳在线运行了,内存爆满卡死的情况不再出现。但是,运维同时发现,在读写混合场景下前端查询的相应时间明显比只读场景下要长,在单节点10线程写入的情况,查询相应几乎都在1s以上。

基础检查结果:YGC周期在1s , Young区回收率正常(5% S区) Old区占用稳定(30%)

猜测可能原因:

  • YGC阶段扫描 String Table Root的时间过长
  • 代码本身存在long loop或者native调用过长的情况

做法:使用Alibaba Dragonwell8 JDK进行detailed gc log分析

更换Dragonwell8 JDK, 引入参数 -XX: PrintGCRootsTraceTime(打印GC Root每个phase的消耗时间)-XX: PrintReferenceGC(打印各类型引用处理时间)-XX: PrintSafepointStatistics (打印安全点统计信息)

Alibaba定制的开源dragonwell JDKAlibaba定制的开源dragonwell JDK
string table roots的scan时间很短string table roots的scan时间很短

使用gc easy统计safe point所占用时间

可见进入safepoints的时间仅占0.3%左右可见进入safepoints的时间仅占0.3%左右
root processing总消耗只在300ms左右root processing总消耗只在300ms左右

排除了以上两个猜测,作者在检查gc.log的过程中,偶然看到如下日志。

FinalReference达到几十万至百万FinalReference达到几十万至百万

如上图,FinalReference的数量爆表,且占用了秒级别的ygc时间,这显然是异常的。

谁触发了finalize? 检查内存快照,发现引用来自JsonXContentParser这个类

修复不正常的JsonXContentParser,重复测试

FinalReference消失FinalReference消失
Ygc时间恢复未正常水平Ygc时间恢复未正常水平

总结

本文针对Skyper在测试过程中发现的JVM内存问题,详述了3个阶段的问题分析过程,诊断方法和修复效果。对于绝大多数的JVM进程来说,GC问题基本上来自本身代码的bug和错误,在没有解决这些问题之前,试图通过简单地调整JVM参数或者更换GC collector的方式获得更好的效果是不可能,更多的时候,需要结合JVM内存快照和gclog进行分析,找到时间具体消耗在哪个阶段和引用具体’粘在‘哪类对象上,才是解决问题的关键。

0 人点赞