Bulk異常引發(fā)的Elasticsearch內(nèi)存泄漏

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

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


Heap Used %

初步排查

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

非常費解是什么東西占著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é)點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é)點的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獨有，后續(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)定性是非常重要的！

最后編輯于 ：
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成，瀏覽時請結(jié)合常識與多方信息審慎甄別。
平臺聲明：文章內(nèi)容（如有圖片或視頻亦包括在內(nèi)）由作者上傳并發(fā)布，文章內(nèi)容僅代表作者本人觀點，簡書系信息發(fā)布平臺，僅提供信息存儲服務(wù)。

相關(guān)閱讀更多精彩內(nèi)容

友情鏈接更多精彩內(nèi)容