Bulk異常引發的Elasticsearch內存泄漏
2018年8月24日更新: 今天放出的6.4版修復了這個問題。
前天公司度假部門一個線上ElasticSearch集群發出報警，有Data Node的Heap使用量持續超過80%警戒線。 收到報警郵件后，不敢怠慢，立即登陸監控系統查看集群狀態。還好，所有的結點都在正常服務，只是有2個結點的Heap使用率非常高。此時，Old GC一直在持續的觸發，卻無法回收內存。
初步排查
問題結點的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的活動線程數量也都非常低。
非常費解是什么東西占着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，一眼看到這20多GB內存主要是被一堆bulk線程實例占用了，每個實例則占用了接近1.5GB的內存。
進入"dominator_tree"面板，按照"Retained Heap"排序，可以看到多個bulk線程的內存占用都非常高。
將其中一個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開發的效率、提升業務的穩定性是非常重要的！