java dump 內存分析 elasticsearch Bulk異常引起的Elasticsearch內存泄漏

Bulk異常引起的Elasticsearch內存泄漏 

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

前天公司度假部門一個線上ElasticSearch集羣發出報警，有Data Node的Heap使用量持續超過80%警惕線。 收到報警郵件後，不敢怠慢，當即登錄監控系統查看集羣狀態。還好，全部的結點都在正常服務，只是有2個結點的Heap使用率很是高。此時，Old GC一直在持續的觸發，卻沒法回收內存。

 

Heap Used %

---

初步排查

問題結點的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的活動線程數量也都很是低。

 

Bulk & Search 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: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開發的效率、提高業務的穩定性是很是重要的！