1、分詞源碼升級一段時間后異常
主要特點:其中幾個數據節點 CPU 負載飆升,線程池阻塞
線上升級完分詞后,線下測試與壓測都沒有什么問題,統一大規模上線一段時間后頻繁的出現數據節點所在的服務器節點 CPU 飈的非常高,查看日志只看到:
java.lang.OutOfMemoryError: unable to create new native thread,但是並沒有從中可以發現有價值的內容。
通過 linux 命令:top、ps aux | grep pid 等命令確定了哪個節點異常后,首先想到是不是數據不均衡導致的,采用:
GET /_cat/segments/xxx_index?v 查看發現 es 經過 hash 計算數據還是比較均衡的。
通過 jstack 打印 Java線程棧的狀態,以及通過 es api 接口查看線程池的狀態:GET _cat/thread_pool,發現 index 時有異常,進一步查看 index 線程池狀態:GET _cat/thread_pool/index
可以 formate:GET /_cat/thread_pool/index?v&h=ip,port,type,name,active,rejected,completed,size,queue,queue_size
這個命令查看到的結果發現 rejected 和 queue 數據量居多,表明拒絕的 和 排隊的持續增高,絕對有異常。那么進而通過命令:GET /_nodes/hot_threads 來查看當前有問題的熱的線程到底在干什么操作,從這里大概就可以看出問題了。定位到是分詞的時候做歧義處理采用遞歸循環導致無法退出卡死的現象。
以上都是通過 es 的 dev_tools 來查看問題。具體和 jstatck pid 查出來的問題是一樣的。
2、批量更新后服務節點異常
主要特點:其中幾個數據節點 內存持續 80%以上,內存泄露
經驗證,es5.x 機器以下版本都存在,es6.x 沒有做驗證,懷疑應該也存在相同問題。
由於新上線一個業務,非要實時局部更新 es,我的態度很明確不允許業務和 es 產生直接關聯,通過中間件的方式,例如:中間表 mysql/TiDB 等數據庫、kafka隊列等,業務只需要關系中間件的數據更新就可以了,至於 es 如何更新是由索引系統來處理,根據 ElasticStack系列之十九 & bulk時 index、create 和 update 的區別 我們可知道,做為專業搜索引擎工程師一般不會使用 update 方式,都會通過拼裝完成的 data 數據直接 index 到 es,技能保證效率,也能降低 es 的負載和內存使用率。但有時候有些事情不以人的意志為轉移,所以最后這個 update 的接口“順利上線”。
不出意料,一段時間后,其中有幾個 data 節點內存持續告警,很明顯 full gc 也解決不了問題,線上同時也出現了超時情況,卡頓頻出。
為了不影響線上業務,首先保留了線程,之后緊急重啟有問題節點,並下線相關接口。之后就平穩了,再來分析問題吧。
通過排查總結如下:
1. 集群的數據量並不大,占用磁盤空間較小
2. 各節點的 segment memory 和 cache 占用量也較小
3. 集群的 QPS大概也 50 左右,CPU 平時消耗最高不到 10%,各類 thread pool 活動線程量都比較低
通過以上 3 排查總結,非常費解是什么東西占着 20 多個 GB 內存不釋放呢?懷疑是 update 相關操作導致,需要進一步查看日志。
日志大量的報以下信息:
[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.5.1.jar:5.5.1]
at org.elasticsearch.action.update.UpdateHelper.prepare(UpdateHelper.java:81) ~[elasticsearch-5.5.1.jar:5.5.1]
這是因為寫入程序會從數據源拿到數據后,根據 doc_id 對ES里的數據做update。會有部分doc_id在ES里不存在的情況,但並不影響業務邏輯,因而ES記錄的document missing異常。
這個日志還不能說明問題,至此別無他法,只能對 JVM 做Dump分析了。
最終發現問題是因為當大量 update es 不存在的 id 時,es 會記錄這些 document missing 異常記錄,記錄的時候使用的 log4j 的 logevent 對一個大的bulk請求對象有強引用而導致其無法被垃圾回收掉,產生內存泄漏。
追蹤 es 底層源碼發現,日志打印的 logevent 因為被一個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.util.Constants里,log4j會根據運行環境判斷是否是WEB應用,如果不是,就從系統參數 log4j2.enable.threadlocals 讀取這個常量,如果沒有設置,則默認值是true。由於ES不是一個web應用,導致log4j選擇使用了ReusableLogEventFactory,因而使用了thread_local來創建 MutableLogEvent 對象,最終在ES記錄bulk exception 這個特殊場景下產生非常顯著的內存泄漏。
參考上面的原因,目前線上采用了兩種方案,當然這兩種方案任何一種都可以解決這類問題:
1. 不允許業務直接通過 update 接口來更新 es 集群
2. 在ES的JVM配置文件jvm.options里,添加一個log4j的系統變量- Dlog4j2.enable.threadlocals=false ,禁用掉thread local即可
3、sug 服務導致服務節點異常
主要特點:其中幾個數據節點 CPU 負載飆升,線程池阻塞
之前針對 sug 做了大規模的調優和業務邏輯優化,上線后運行良好,但是一段時間后其中有幾個 es data 節點負載飆升,影響整個服務穩定。相關日志如下:
[ERROR][o.e.b.ElasticsearchUncaughtExceptionHandler] [xx.xx.xx.xx] fatal error in thread [elasticsearch[xx.xx.xx.xx][search][T#29]], exiting java.lang.StackOverflowError at org.apache.lucene.util.automaton.Operations.isFinite(Operations.java:1053)
調查后發現,由於業務接口並沒有對 query 長度做任何校驗和限制,有些惡意攻擊或者刷數據的情況導致使用 Prefix/Regex/Fuzzy 一類的 Query,是直接構造的 deterministic automaton,如果查詢字符串過長,或者pattern本身過於復雜,構造出來的狀態過多,之后一個isFinite的Lucene方法調用可能產生堆棧溢出。
對於我們這次特定的問題,是因為prefix Query里沒有限制用戶輸入的長度。看ES的源碼,PrefixQuery繼承自Lucene的AutomatonQuery,在實例化的時候,maxDeterminizedStates傳的是Integer.MAX_VALUE, 並且生成automaton之前,prefix的長度也沒有做限制。 個人認為這里可能應該限制一下大小,避免產生過多的狀態。 最終拋出異常的代碼是
org.apache.lucene.util.automaton.Operations.isFinite,可以知道這段代碼里用了遞歸,遞歸的深度取決於狀態轉移的數量。因為使用了遞歸,可能導致堆棧溢出。
由此可見,在項目里使用了模糊查詢的同學,一定一定要注意限制用戶輸入長度,否則可能導致集群負載過高或者整個掛掉。