前天公司度假部门一个线上ElasticSearch集群发出报警，有Data Node的Heap使用量持续超过80%警戒线。 收到报警邮件后，不敢怠慢，立即登陆监控系统查看集群状态。还好，所有的结点都在正常服务，只是有2个结点的Heap使用率非常高。此时，Old GC一直在持续的触发，却无法回收内存。
Heap Used %
初步排查
问题结点的Heap分配了30GB，80%的使用率约等于24GB。 但集群的数据总量并不大，5个结点所有索引文件加起来占用的磁盘空间还不到10GB。
GET /_cat/allocation?v&h=shards,disk.indices,disk.used,disk.avail
shards disk.indices disk.used disk.avail
3 1.9gb 38.3gb 89.7gb
4 2.2gb 13.4gb 114.6gb
4 2.5gb 20.3gb 107.7gb
4 2.3gb 33.9gb 94.1gb
3 1.7gb 12.8gb 115.2gb
查看各结点的segment memory和cache占用量也都非常小，是MB级别的。
GET /_cat/nodes?v&h=id,port,v,m,fdp,mc,mcs,sc,sm,qcm,fm,im,siwm,svmm
id port v m fdp mc mcs sc sm qcm fm siwm svmm
e1LV 9300 5.3.2 - 1 0 0b 68 69mb 1.5mb 1.9mb 0b 499b
5VnU 9300 5.3.2 - 1 0 0b 75 79mb 1.5mb 1.9mb 0b 622b
_Iob 9300 5.3.2 - 1 0 0b 56 55.7mb 1.3mb 914.1kb 0b 499b
4Kyl 9300 5.3.2 * 1 1 330.1mb 81 84.4mb 1.2mb 1.9mb 0b 622b
XEP_ 9300 5.3.2 - 1 0 0b 45 50.4mb 748.5kb 1mb 0b 622b
集群的QPS只有30上下，CPU消耗10%都不到，各类thread pool的活动线程数量也都非常低。
Bulk & Search 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个步骤:
- 获取二进制的head dump文件
jmap -dump:format=b,file=/tmp/es_heap.bin <pid>其中pid是ES JAVA进程的进程号。 - 将生成的dump文件下载到本地开发机器，启动MAT，从其GUI打开文件。
要注意，MAT本身也是JAVA应用，需要有JDK运行环境的支持。
MAT第一次打dump文件的时候，需要对其解析，生成多个索引。这个过程比较消耗CPU和内存，但一旦完成，之后再打开dump文件就很快，消耗很低。 对于这种20多GB的大文件，第一次解析的过程会非常缓慢，并且很可能因为开发机内存的较少而内存溢出。因此，我找了台大内存的服务器来做第一次的解析工作:
- 将linux版的MAT拷贝上去，解压缩后，修改配置文件MemoryAnalyzer.ini，将内存设置为20GB左右:
这样能保证解析的过程中不会内存溢出。$ cat MemoryAnalyzer.ini -startup plugins/org.eclipse.equinox.launcher_1.3.100.v20150511-1540.jar --launcher.library plugins/org.eclipse.equinox.launcher.gtk.linux.x86_64_1.1.300.v20150602-1417 -vmargs -Xmx20240m - 将dump文件拷贝上去，执行下面几个命令生成索引及3个分析报告:
mat/ParseHeapDump.sh es_heap.bin org.eclipse.mat.api:suspectsmat/ParseHeapDump.sh es_heap.bin org.eclipse.mat.api:overviewmat/ParseHeapDump.sh es_heap.bin org.eclipse.mat.api:top_components
分析成功以后，会生成如下一堆索引文件(.index)和分析报告(.zip)
-rw-r--r--@ 1 xgwu staff 62M Nov 6 16:18 es_heap.a2s.index
-rw-r--r--@ 1 xgwu staff 25G Nov 6 14:59 es_heap.bin
-rw-r--r--@ 1 xgwu staff 90M Nov 6 16:21 es_heap.domIn.index
-rw-r--r--@ 1 xgwu staff 271M Nov 6 16:21 es_heap.domOut.index
-rw-r--r-- 1 xgwu staff 144K Nov 7 18:38 es_heap.i2sv2.index
-rw-r--r--@ 1 xgwu staff 220M Nov 6 16:18 es_heap.idx.index
-rw-r--r--@ 1 xgwu staff 356M Nov 6 16:20 es_heap.inbound.index
-rw-r--r--@ 1 xgwu staff 6.8M Nov 6 16:20 es_heap.index
-rw-r--r--@ 1 xgwu staff 76M Nov 6 16:18 es_heap.o2c.index
-rw-r--r--@ 1 xgwu staff 231M Nov 6 16:20 es_heap.o2hprof.index
-rw-r--r--@ 1 xgwu staff 206M Nov 6 16:21 es_heap.o2ret.index
-rw-r--r--@ 1 xgwu staff 353M Nov 6 16:20 es_heap.outbound.index
-rw-r--r--@ 1 xgwu staff 399K Nov 6 16:16 es_heap.threads
-rw-r--r--@ 1 xgwu staff 89K Nov 7 17:40 es_heap_Leak_Suspects.zip
-rw-r--r--@ 1 xgwu staff 78K Nov 6 19:22 es_heap_System_Overview.zip
-rw-r--r--@ 1 xgwu staff 205K Nov 6 19:22 es_heap_Top_Components.zip
drwxr-xr-x@ 3 xgwu staff 96B Nov 6 16:15 workspace
将这些文件打包下载到本地机器上，用MAT GUI打开就可以分析了。
在MAT里打开dump文件的时候，可以选择打开已经生成好的报告，比如Leak suspects:
选择打开leak Suspects报告
通过Leak Suspects，一眼看到这20多GB内存主要是被一堆bulk线程实例占用了，每个实例则占用了接近1.5GB的内存。
Leak Suspects
进入"dominator_tree"面板，按照"Retained Heap"排序，可以看到多个bulk线程的内存占用都非常高。
Dominator Tree
将其中一个thread的引用链条展开，看看这些线程是如何Retain这么多内存的，特别注意红圈部分:
对象引用链
这个引用关系解读如下:
- 这个bulk线程的thread local map里保存了一个log4j的
MultableLogEvent对象。 -
MutablelogEvent对象引用了log4j的ParameterizedMessage对象。 -
ParameterizedMessage引用了bulkShardRequest对象。 -
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开发的效率、提升业务的稳定性是非常重要的！
网友评论