java dump 内存分析 elasticsearch Bulk异常引起的Elasticsearch内存泄漏

时间  2019-11-06
标签 java dump 内存 分析 elasticsearch bulk 异常 引起 泄漏 栏目 Java 繁體版
原文   原文链接

Bulk异常引起的Elasticsearch内存泄漏 

2018年8月24日更新: 今天放出的6.4版修复了这个问题。php

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


 
Heap Used %

初步排查

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

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级别的。node

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的活动线程数量也都很是低。linux


 
Bulk & Search Thread Pool

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

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

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

[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异常应该能够忽略。apache

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

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: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)

-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这么多内存的，特别注意红圈部分:


 
对象引用链

这个引用关系解读以下:

  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开发的效率、提高业务的稳定性是很是重要的！

相关文章
相关标签/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公众号
   欢迎关注本站公众号,获取更多信息
联系我们 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程