Bulk 异常引发的 Elasticsearch 内存泄漏

运维线上 ES 集群时，偶然遇到内存泄露的问题，排查问题时看到了这篇文章，清晰明了，所以分享给大家，希望给大家问题排查提供一些思路。

背景介绍

前天公司度假部门一个线上 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 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 类型的变量。

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

结束

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

本文转载自公众号 360 云计算（ID：hulktalk）。

原文链接：

https://mp.weixin.qq.com/s/GH4smJgUcfFQ0q_l2Y8ipA