Bulk 异常引发的 Elasticsearch 内存泄漏

女主宣言

背景介绍

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

问题排查

[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 final ThreadNameCachingStrategy 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类型的变量。

参考上面的文档后，也为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开发的效率、提升业务的稳定性是非常重要的！