2018年8月24日更新: 今天放出的6.4版修復(fù)了這個問題。

前天公司度假部門一個線上ElasticSearch集群發(fā)出報警谣殊，有Data Node的Heap使用量持續(xù)超過80%警戒線。 收到報警郵件后，不敢怠慢，立即登陸監(jiān)控系統(tǒng)查看集群狀態(tài)笙僚。還好，所有的結(jié)點(diǎn)都在正常服務(wù)灵再，只是有2個結(jié)點(diǎn)的Heap使用率非常高肋层。此時亿笤，Old GC一直在持續(xù)的觸發(fā)，卻無法回收內(nèi)存栋猖。

Heap Used %

初步排查

問題結(jié)點(diǎn)的Heap分配了30GB净薛，80%的使用率約等于24GB。 但集群的數(shù)據(jù)總量并不大蒲拉，5個結(jié)點(diǎn)所有索引文件加起來占用的磁盤空間還不到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

查看各結(jié)點(diǎn)的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的活動線程數(shù)量也都非常低锦援。

Bulk & Search Thread Pool

非常費(fèi)解是什么東西占著20多GB的內(nèi)存不釋放猛蔽？

出現(xiàn)問題的集群ES版本是5.3.2，而這個版本的穩(wěn)定性在公司內(nèi)部已經(jīng)經(jīng)過長時間的考驗雨涛，做為穩(wěn)定版本在線上進(jìn)行了大規(guī)模部署枢舶。 其他一些讀寫負(fù)載非常高的集群也未曾出現(xiàn)過類似的狀況，看來是遇到新問題了替久。

查看問題結(jié)點(diǎn)ES的日志，除了看到一些Bulk異常以外躏尉，未見特別明顯的其他和資源相關(guān)的錯誤:

[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][á∫≥ê?o?∞?ê?ú??∑_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]

和用戶確認(rèn)這些異常的原因蚯根，是因為寫入程序會從數(shù)據(jù)源拿到數(shù)據(jù)后，根據(jù)doc_id對ES里的數(shù)據(jù)做update胀糜。會有部分doc_id在ES里不存在的情況颅拦，但并不影響業(yè)務(wù)邏輯，因而ES記錄的document missing異常應(yīng)該可以忽略教藻。

至此別無他法距帅，只能對JVM做Dump分析了。

Heap Dump分析

用的工具是Eclipse MAT括堤，從這里下載的Mac版:Downloads 碌秸。 使用這個工具需要經(jīng)過以下2個步驟:

• 獲取二進(jìn)制的head dump文件 jmap -dump:format=b,file=/tmp/es_heap.bin <pid> 其中pid是ES JAVA進(jìn)程的進(jìn)程號。
• 將生成的dump文件下載到本地開發(fā)機(jī)器悄窃，啟動MAT讥电，從其GUI打開文件。

要注意轧抗，MAT本身也是JAVA應(yīng)用恩敌，需要有JDK運(yùn)行環(huán)境的支持。

MAT第一次打dump文件的時候横媚，需要對其解析纠炮，生成多個索引月趟。這個過程比較消耗CPU和內(nèi)存，但一旦完成恢口，之后再打開dump文件就很快狮斗，消耗很低。 對于這種20多GB的大文件弧蝇，第一次解析的過程會非常緩慢碳褒，并且很可能因為開發(fā)機(jī)內(nèi)存的較少而內(nèi)存溢出。因此看疗，我找了臺大內(nèi)存的服務(wù)器來做第一次的解析工作:

• 將linux版的MAT拷貝上去沙峻，解壓縮后，修改配置文件MemoryAnalyzer.ini两芳，將內(nèi)存設(shè)置為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
  

  這樣能保證解析的過程中不會內(nèi)存溢出摔寨。
• 將dump文件拷貝上去，執(zhí)行下面幾個命令生成索引及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

將這些文件打包下載到本地機(jī)器上是复，用MAT GUI打開就可以分析了。

在MAT里打開dump文件的時候竖螃，可以選擇打開已經(jīng)生成好的報告淑廊，比如Leak suspects:

選擇打開leak Suspects報告

通過Leak Suspects，一眼看到這20多GB內(nèi)存主要是被一堆bulk線程實例占用了特咆，每個實例則占用了接近1.5GB的內(nèi)存季惩。

Leak Suspects

進(jìn)入"dominator_tree"面板，按照"Retained Heap"排序腻格，可以看到多個bulk線程的內(nèi)存占用都非常高画拾。

Dominator Tree

將其中一個thread的引用鏈條展開，看看這些線程是如何Retain這么多內(nèi)存的菜职，特別注意紅圈部分:

對象引用鏈

這個引用關(guān)系解讀如下:

1. 這個bulk線程的thread local map里保存了一個log4j的MultableLogEvent對象青抛。
2. MutablelogEvent對象引用了log4j的ParameterizedMessage對象。
3. ParameterizedMessage引用了bulkShardRequest對象酬核。
4. bulkShardRequest引用了4萬多個BulkitemRequest對象蜜另。

這樣看下來，似乎是log4j的logevent對一個大的bulk請求對象有強(qiáng)引用而導(dǎo)致其無法被垃圾回收掉愁茁，產(chǎn)生內(nèi)存泄漏蚕钦。

聯(lián)想到ES日志里，有記錄一些document missing的bulk異常鹅很，猜測是否在記錄這些異常的時候產(chǎn)生的泄漏嘶居。

問題復(fù)現(xiàn)

為了驗證猜測，我在本地開發(fā)機(jī)上，啟動了一個單結(jié)點(diǎn)的5.3.2測試集群邮屁，用bulk api做批量的update整袁，并且有意為其中1個update請求設(shè)置不存在的doc_id。為了便于測試佑吝，我在ES的配置文件elasticsearch.yml里添加了配置項processors: 1坐昙。 這個配置項影響集群thread_pool的配置，bulk thread pool的大小將減少為1個芋忿，這樣可以更快速和便捷的做各類驗證炸客。

啟動集群，發(fā)送完bulk請求后戈钢，立即做一個dump痹仙，重復(fù)之前的分析過程，問題得到了復(fù)現(xiàn)殉了。 這時候想开仰，是否其他bulk異常也會引起同樣的問題，比如寫入的數(shù)據(jù)和mapping不匹配薪铜？ 測試了一下众弓，問題果然還是會產(chǎn)生。再用不同的bulk size進(jìn)行測試隔箍，發(fā)現(xiàn)無法回收的這段內(nèi)存大小谓娃，取決于最后一次拋過異常的bulk size大小。至此鞍恢，基本可以確定內(nèi)存泄漏與log4j記錄異常消息的邏輯有關(guān)系傻粘。

為了搞清楚這個問題是否5.3.2獨(dú)有，后續(xù)版本是否有修復(fù)帮掉，在最新的5.6.3上做了同樣的測試，問題依舊窒典，因此這應(yīng)該是一個還未發(fā)現(xiàn)的深層Bug.

讀源碼查根源

大致搞清楚問題查找的方向了蟆炊，但根源還未找到，也就不知道如何修復(fù)和避免瀑志，只有去扒源碼了涩搓。
在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做為一個參數(shù)傳入了。這里的request是一個BulkShardRequest對象战得，保存的是要寫入到一個shard的一批bulk item request充边。 這樣以來，一個批次寫入的請求數(shù)量越多，這個對象retain的內(nèi)存就越多浇冰。 可問題是贬媒，為什么logger.debug（）調(diào)用完畢以后，這個引用不會被釋放肘习？

通過和之前MAT上的dominator tree仔細(xì)對比际乘，可以看到ParameterizedMessage之所以無法釋放，是因為被一個MutableLogEvent在引用漂佩，而這個MutableLogEvent被做為一個thread local存放起來了脖含。 由于ES的Bulk thread pool是fix size的，也就是預(yù)先創(chuàng)建好投蝉，不會銷毀和再創(chuàng)建养葵。 那么這些MutableLogEvent對象由于是thread local的，只要線程沒有銷毀墓拜，就會對該線程實例一直全局存在港柜，并且其還會一直引用最后一次處理過的ParameterizedMessage。 所以在ES記錄bulk exception這種比較大的請求情況下咳榜， 整個request對象會被thread local變量一直強(qiáng)引用無法釋放夏醉，產(chǎn)生大量的內(nèi)存泄漏。

再繼續(xù)挖一下log4j的源碼涌韩，發(fā)現(xiàn)MutableLogEvent是在org.apache.logging.log4j.core.impl.ReusableLogEventFactory里做為thread local創(chuàng)建的畔柔。

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則根據(jù)一個常數(shù)ENABLE_THREADLOCALS的值來決定用哪個LogEventFactory。

        if (LOG_EVENT_FACTORY == null) {
            LOG_EVENT_FACTORY = Constants.ENABLE_THREADLOCALS
                    ? new ReusableLogEventFactory()
                    : new DefaultLogEventFactory();
        }

繼續(xù)深挖臣樱，在org.apache.logging.log4j.util.Constants里看到靶擦，log4j會根據(jù)運(yùn)行環(huán)境判斷是否是WEB應(yīng)用，如果不是雇毫，就從系統(tǒng)參數(shù)log4j2.enable.threadlocals讀取這個常量玄捕，如果沒有設(shè)置，則默認(rèn)值是true棚放。

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

由于ES不是一個web應(yīng)用枚粘，導(dǎo)致log4j選擇使用了ReusableLogEventFactory，因而使用了thread_local來創(chuàng)建MutableLogEvent對象飘蚯，最終在ES記錄bulk exception這個特殊場景下產(chǎn)生非常顯著的內(nèi)存泄漏馍迄。

再問一個問題，為何log4j要將logevent做為thread local創(chuàng)建局骤？ 跑到log4j的官網(wǎng)去扒了一下文檔攀圈，在這里 Garbage-free Steady State Logging 找到了合理的解釋。 原來為了減少記錄日志過程中的反復(fù)創(chuàng)建的對象數(shù)量峦甩，減輕GC壓力從而提高性能赘来，log4j有很多地方使用了thread_local來重用變量。 但使用thread local字段裝載非JDK類，可能會產(chǎn)生內(nèi)存泄漏問題撕捍，特別是對于web應(yīng)用拿穴。 因此才會在啟動的時候判斷運(yùn)行環(huán)境，對于web應(yīng)用會禁用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找到了規(guī)避這個問題的措施： 在ES的JVM配置文件jvm.options里，添加一個log4j的系統(tǒng)變量-Dlog4j2.enable.threadlocals=false，禁用掉thread local即可。 經(jīng)過測試燕锥，該選項可以有效避開這個內(nèi)存泄漏問題根蟹。

這個問題Github上也提交了Issue生宛，對應(yīng)的鏈接是: Memory leak upon partial TransportShardBulkAction failure

寫在最后

ES的確是非常復(fù)雜的一個系統(tǒng)，包含非常多的模塊和第三方組件，可以支持很多想象不到的用例場景，但一些邊緣場景可能會引發(fā)一些難以排查的問題椿每。完備的監(jiān)控體系和一個經(jīng)驗豐富的支撐團(tuán)隊對于提升業(yè)務(wù)開發(fā)人員使用ES開發(fā)的效率、提升業(yè)務(wù)的穩(wěn)定性是非常重要的英遭！