Bulk 异常引起的 Elasticsearch 内存泄漏

女主宣言

运维线上ES集群时，偶然遇到内存泄露的问题，排查问题时看到了这篇文章，清晰明了，因此分享给你们，但愿给你们问题排查提供一些思路。

本文转载自简书，如遇版权问题，请及时联系小编。

PS：丰富的一线技术、多元化的表现形式，尽在“ HULK一线技术杂谈 ”，点关注哦！

背景介绍

前天公司度假部门一个线上ElasticSearch集群发出报警，有Data Node的Heap使用量持续超过80%警惕线。 收到报警邮件后，不敢怠慢，当即登录监控系统查看集群状态。还好，全部的节点都在正常服务，只是有2个节点的Heap使用率很是高。此时，Old GC一直在持续的触发，却没法回收内存。

问题排查

问题节点的Heapsize分配了30GB，80%的使用率约等于24GB。 但集群的数据总量并不大，5个节点全部索引文件加起来占用的磁盘空间还不到10GB。

查看各节点的segment memory和cache占用量也都很是小，是MB级别的。

集群的QPS只有30上下，CPU消耗10%都不到，各种thread pool的活动线程数量也都很是低。

很是费解是什么东西占着20多GB的内存不释放？

出现问题的集群ES版本是5.3.2，而这个版本的稳定性在公司内部已经通过长时间的考验，作为稳定版本在线上进行了大规模部署。 其余一些读写负载很是高的集群也不曾出现过相似的情况，看来是遇到新问题了。

查看问题节点ES的日志，除了看到一些Bulk异常之外，未见特别明显的其余和资源相关的错误:

[2017-11-06T16:33:15,668][DEBUG][o.e.a.b.TransportShardBulkAction] [] [suggest-3][0] failed to execute bulk item (update) BulkShardRequest [[suggest-3][0]] containing [44204 ] requests org.elasticsearch.index.engine.DocumentMissingException: [ type ][纳格尔果德_1198]: document missing at org.elasticsearch.action.update.UpdateHelper.prepare(UpdateHelper.java:92) ~[elasticsearch-5.3.2.jar:5.3.2] at org.elasticsearch.action.update.UpdateHelper.prepare(UpdateHelper.java:81) ~[elasticsearch-5.3.2.jar:5.3.2]

和用户确认这些异常的缘由，是由于写入程序会从数据源拿到数据后，根据doc_id对ES里的数据作update。会有部分doc_id在ES里不存在的状况，但并不影响业务逻辑，于是ES记录的document missing异常应该能够忽略。

至此别无他法，只能对JVM作Dump分析了。

Heap Dump分析

用的工具是Eclipse MAT，从这里下载的Mac版:Downloads 。 使用这个工具须要通过如下2个步骤:

1. 获取二进制的head dump文件 jmap -dump:format=b,file=/tmp/es_heap.bin <pid> 其中pid是ES JAVA进程的进程号。

2. 将生成的dump文件下载到本地开发机器，启动MAT，从其GUI打开文件。

要注意，MAT自己也是JAVA应用，须要有JDK运行环境的支持。

MAT第一次打dump文件的时候，须要对其解析，生成多个索引。这个过程比较消耗CPU和内存，但一旦完成，以后再打开dump文件就很快，消耗很低。 对于这种20多GB的大文件，第一次解析的过程会很是缓慢，而且极可能由于开发机内存的较少而内存溢出。所以，我找了台大内存的服务器来作第一次的解析工做:

1.将linux版的MAT拷贝上去，解压缩后，修改配置文件MemoryAnalyzer.ini，将内存设置为20GB左右:

这样能保证解析的过程当中不会内存溢出。

2.将dump文件拷贝上去，执行下面几个命令生成索引及3个分析报告:

mat/ParseHeapDump.sh es_heap.bin org.eclipse.mat.api:suspects

mat/ParseHeapDump.sh es_heap.bin org.eclipse.mat.api:overview

mat/ParseHeapDump.sh es_heap.bin org.eclipse.mat.api:top_components

分析成功之后，会生成以下一堆索引文件(.index)和分析报告(.zip)

将这些文件打包下载到本地机器上，用MAT GUI打开就能够分析了。

在MAT里打开dump文件的时候，能够选择打开已经生成好的报告，好比Leak suspects:

经过Leak Suspects，一眼看到这20多GB内存主要是被一堆bulk线程实例占用了，每一个实例则占用了接近1.5GB的内存。

进入"dominator_tree"面板，按照"Retained Heap"排序，能够看到多个bulk线程的内存占用都很是高。

将其中一个thread的引用链条展开，看看这些线程是如何Retain这么多内存的，特别注意红圈部分:

这个引用关系解读以下:

1. 这个bulk线程的thread local map里保存了一个log4j的MultableLogEvent对象。

2. MutablelogEvent对象引用了log4j的ParameterizedMessage对象。

3. ParameterizedMessage引用了bulkShardRequest对象。

4. bulkShardRequest引用了4万多个BulkitemRequest对象。

这样看下来，彷佛是log4j的logevent对一个大的bulk请求对象有强引用而致使其没法被垃圾回收掉，产生内存泄漏。

联想到ES日志里，有记录一些 document missing 的bulk异常，猜想是否在记录这些异常的时候产生的泄漏。

问题复现

为了验证猜想，我在本地开发机上，启动了一个单节点的5.3.2测试集群，用bulk api作批量的update，而且有意为其中1个update请求设置不存在的doc_id。

为了便于测试，我在ES的配置文件elasticsearch.yml里添加了配置项processors: 1。 这个配置项影响集群thread_pool的配置，bulk thread pool的大小将减小为1个，这样能够更快速和便捷的作各种验证。

启动集群，发送完bulk请求后，当即作一个dump，重复以前的分析过程，问题获得了复现。

这时候想，是否其余bulk异常也会引发一样的问题，好比写入的数据和mapping不匹配？ 测试了一下，问题果真仍是会产生。再用不一样的bulk size进行测试，发现没法回收的这段内存大小，取决于最后一次抛过异常的bulk size大小。至此，基本能够肯定内存泄漏与log4j记录异常消息的逻辑有关系。

为了搞清楚这个问题是否5.3.2独有，后续版本是否有修复，在最新的5.6.3上作了一样的测试，问题依旧，所以这应该是一个还未发现的深层Bug.

读源码查根源

大体搞清楚问题查找的方向了，但根源还未找到，也就不知道如何修复和避免，只有去扒源码了。

在TransportShardBulkAction 第209行，找到了ES日志里抛异常的代码片断。

if (isConflictException(failure)) {

logger.trace((Supplier<?>) () -> new ParameterizedMessage("{} failed to execute bulk item ({}) {}",

request.shardId(), docWriteRequest.opType().getLowercase(), request), failure);

} else {

logger.debug((Supplier<?>) () -> new ParameterizedMessage("{} failed to execute bulk item ({}) {}",

request.shardId(), docWriteRequest.opType().getLowercase(), request), failure);

}

这里看到了ParameterizedMessage实例化过程当中，request作为一个参数传入了。这里的request是一个BulkShardRequest对象，保存的是要写入到一个shard的一批bulk item request。 这样以来，一个批次写入的请求数量越多，这个对象retain的内存就越多。 可问题是，为何logger.debug（）调用完毕之后，这个引用不会被释放？

经过和以前MAT上的dominator tree仔细对比，能够看到ParameterizedMessage之因此没法释放，是由于被一个MutableLogEvent在引用，而这个MutableLogEvent被作为一个thread local存放起来了。 因为ES的Bulk thread pool是fix size的，也就是预先建立好，不会销毁和再建立。 那么这些MutableLogEvent对象因为是thread local的，只要线程没有销毁，就会对该线程实例一直全局存在，而且其还会一直引用最后一次处理过的ParameterizedMessage。 因此在ES记录bulk exception这种比较大的请求状况下， 整个request对象会被thread local变量一直强引用没法释放，产生大量的内存泄漏。

再继续挖一下log4j的源码，发现MutableLogEvent是在org.apache.logging.log4j.core.impl.ReusableLogEventFactory里作为thread local建立的。

public class ReusableLogEventFactory implements LogEventFactory { private static finalThreadNameCachingStrategy THREAD_NAME_CACHING_STRATEGY = ThreadNameCachingStrategy.create(); private static final Clock CLOCK = ClockFactory.getClock(); private static ThreadLocal<MutableLogEvent> mutableLogEventThreadLocal = new ThreadLocal<>();

而org.apache.logging.log4j.core.config.LoggerConfig则根据一个常数ENABLE_THREADLOCALS的值来决定用哪一个LogEventFactory。

if (LOG_EVENT_FACTORY == null) {

LOG_EVENT_FACTORY = Constants.ENABLE_THREADLOCALS

? new ReusableLogEventFactory()

: new DefaultLogEventFactory();}

继续深挖，在org.apache.logging.log4j.util.Constants里看到，log4j会根据运行环境判断是不是WEB应用，若是不是，就从系统参数log4j2.enable.threadlocals读取这个常量，若是没有设置，则默认值是true。

public static final boolean ENABLE_THREADLOCALS = !IS_WEB_APP && PropertiesUtil.getProperties().getBooleanProperty( "log4j2.enable.threadlocals", true);

因为ES不是一个web应用，致使log4j选择使用了ReusableLogEventFactory，于是使用了thread_local来建立MutableLogEvent对象，最终在ES记录bulk exception这个特殊场景下产生很是显著的内存泄漏。

再问一个问题，为什么log4j要将logevent作为thread local建立？ 跑到log4j的官网去扒了一下文档，在这里 Garbage-free Steady State Logging 找到了合理的解释。 原来为了减小记录日志过程当中的反复建立的对象数量，减轻GC压力从而提升性能，log4j有不少地方使用了thread_local来重用变量。 但使用thread local字段装载非JDK类，可能会产生内存泄漏问题，特别是对于web应用。 所以才会在启动的时候判断运行环境，对于web应用会禁用thread local类型的变量。

“

ThreadLocal fields holding non-JDK classes can cause memory leaks in web applications when the application server’s thread pool continues to reference these fields after the web application is undeployed. To avoid causing memory leaks, Log4j will not use these ThreadLocals when it detects that it is used in a web application (when the javax.servlet.Servlet class is in the classpath, or when system property log4j2.is.webapp is set to "true").

参考上面的文档后，也为ES找到了规避这个问题的措施： 在ES的JVM配置文件jvm.options里，添加一个log4j的系统变量- Dlog4j2.enable.threadlocals=false ，禁用掉thread local便可。 通过测试，该选项能够有效避开这个内存泄漏问题。

这个问题Github上也提交了Issue，对应的连接是: Memory leak upon partial TransportShardBulkAction failure

https://github.com/elastic/elasticsearch/issues/27300

ES的确是很是复杂的一个系统，包含很是多的模块和第三方组件，能够支持不少想象不到的用例场景，但一些边缘场景可能会引起一些难以排查的问题。完备的监控体系和一个经验丰富的支撑团队对于提高业务开发人员使用ES开发的效率、提高业务的稳定性是很是重要的！