Bulk 異常引發的 Elasticsearch 記憶體洩漏

女主宣言

背景介紹

前天公司度假部門一個線上ElasticSearch叢集發出報警，有Data Node的Heap使用量持續超過80%警戒線。 收到報警郵件後，不敢怠慢，立即登陸監控系統檢視叢集狀態。還好，所有的節點都在正常服務，只是有2個節點的Heap使用率非常高。此時，Old GC一直在持續的觸發，卻無法回收記憶體。

問題排查

[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 finalThreadNameCachingStrategy 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型別的變數。

參考上面的文件後，也為ES找到了規避這個問題的措施： 在ES的JVM配置檔案jvm.options裡，新增一個log4j的系統變數- Dlog4j2.enable.threadlocals=false ，禁用掉thread local即可。 經過測試，該選項可以有效避開這個記憶體洩漏問題。

這個問題Github上也提交了Issue，對應的連結是: Memory leak upon partial TransportShardBulkAction failure

https://github.com/elastic/elasticsearch/issues/27300

ES的確是非常複雜的一個系統，包含非常多的模組和第三方元件，可以支援很多想象不到的用例場景，但一些邊緣場景可能會引發一些難以排查的問題。完備的監控體系和一個經驗豐富的支撐團隊對於提升業務開發人員使用ES開發的效率、提升業務的穩定性是非常重要的！