作者：vivo 網際網路資料庫團隊- Liu Huang

本文介紹了一次排查Elasticsearch node_concurrent_recoveries 引發的效能問題的過程。

一、故障描述

1.1 故障現象

1. 業務反饋

業務部分讀請求丟擲請求超時的錯誤。

2. 故障定位資訊獲取

故障開始時間

19:30左右開始

故障丟擲異常紀錄檔

錯誤紀錄檔丟擲timeout錯誤。

故障之前的幾個小時業務是否有進行發版迭代。

未進行相關的發版迭代。

故障的時候流量是否有出現抖動和突刺情況。

內部監控平臺觀察業務側並沒有出現流量抖動和突刺情況。

故障之前的幾個小時Elasticsearch叢集是否有出現相關的變更操作。

Elasticsearch叢集沒有做任何相關的變更操作。

1.2 環境

Elaticsearch的版本：6.x。
叢集規模：叢集資料節點超過30+。

二、故障定位

我們都知道Elasticsearch是一個分散式的資料庫，一般情況下每一次查詢請求協調節點會將請求分別路由到具有查詢索引的各個分片的範例上，然後範例本身進行相關的query和fetch，然後將查詢結果彙總到協調節點返回給使用者端，因此存在木桶效應問題，查詢的整體效能則是取決於是查詢最慢的範例上。所以我們需要確認導致該故障是叢集整體的問題還是某些範例的問題導致的。

2.1 叢集還是範例的問題

1. 檢視所有範例的關鍵監控指標

從監控圖可以很明顯的綠色監控指標代表的範例在19:30左右開始是存在異常現象，在這裡我們假設該範例叫做A。

範例A的指標es.node.threadpool.search.queue的值長時間達到了1000，說明讀請求的佇列已經滿了。
範例A的指標es.node.threadpool.search.rejected的值高峰期到了100+，說明範例A無法處理來自於業務的所有請求，有部分請求是失敗的。
叢集整體的指標es.node.threadpool.search.completed有出現增長，經過業務溝通和內部平臺監控指標的觀察，業務流量平緩，並沒有出現抖動現象，但是使用者端有進行異常重試機制，因此出現增長是因為重試導致。
範例A的指標es.node.threadpool.search.completed相比叢集其他範例高50%以上，說明範例A上存在一個到多個熱點索引。
範例A的指標es.node.threadpool.cpu.percent的值有50%以上的增長。
可通過指標es.node.indices.search.querytime和es.node.indices.search.querytimeinmillis的趨勢可範例級別的請求耗時大致情況。

通過上面的分析，我們能給確認的是範例A是存在異常，但是導致業務請求超時是否是範例A異常導致，還需進一步分析確認。

2.2 範例異常的原因

到了這一步，我們能夠非常明確範例是存在異常情況，接下來我們需要定位是什麼導致範例異常。在這裡我們觀察下範例所在機器的MEM.CACHED、DISK.nvme0n1.IO.UTIL、CPU.SERVER.LOADAVG.PERCORE、CPU.IDLE這些CPU、MEMMORY、DISK IO等指標。

1. CPU or IO

通過監控，我們可以很明顯的看得到，DISK.nvme0n1.IO.UTIL、CPU.SERVER.LOADAVG.PERCORE、CPU.IDLE這三個監控指標上是存在異常情況的。

DISK.nvme0n1.IO.UTIL上深紅色和深褐色指標代表的機器IO使用率存在異常，在這裡我們假設深紅色的機器叫做X，深褐色的機器叫做Y。

CPU.SERVER.LOADAVG.PERCORE和CPU.IDLE這倆個反應CPU使用情況的指標上代表綠色的機器在存在異常，在這裡我們假設綠色的機器叫做Z。

機器X的IO在故障時間之前就處於滿載情況，機器X在整個過程當中是沒有出現波動，因此可移除機器X可能導致叢集受到影響。
機器Y的IO在故障時間之前是處於滿載情況，但是在故障期間IO使用率差不多下降到了50%，因此可移除機器Y可能導致叢集受到影響。
機器Z的CPU使用率在在故障期間直線下降，CPU.IDLE直接下降到個位數；CPU.SERVER.LOADAVG.PERCORE（是單核CPU的平均負載，2.5表示當前負載是CPU核數*2.5）直接增長了4倍，此時整個機器幾乎都是處於阻塞的情況；DISK.nvme0n1.IO.UTIL則是從20%增長到了50%左右。其中CPU的指標是直線增長，IO的指標則是一個曲線增長。

異常範例A所在的機器是Z，目前機器Z的CPU和IO都存在增長情況，其中CPU已經到了系統的瓶頸，系統已經受到了阻塞，IO的利用率從20%增長到了50%，雖然有所增長，但是還未到達磁碟的瓶頸。

通過上面的分析，我們比較傾向於機器Z的CPU的異常導致了範例A的異常。這個時候我們需要確認是什麼原因導致了機器Z的CPU異常，這個時候可通過內部監控平臺的快照檢視機器Z的快照資訊。

通過內部監控平臺的快照，我們可以看到PID為225543的CPU使用率是2289.66%，166819的CPU的使用率是1012.88%。需要注意的是我們機器Z的邏輯核是32C，因此我們可認為CPU機器CPU的使用率理論上最高是3200%。但是使用率CPU最高的倆個範例的值加起來已經是超過了這個值，說明CPU資源已經是完全被使用完畢了的。

通過登陸機器Z，查詢獲取得到PID為225543的程序就是範例A的elasticsearch程序。

2. 範例CPU異常的原因

其實Elasticsearch本身是有介面提供獲取範例上的熱點程序，但是當時執行介面命令的時候長時間沒有獲取到結果，因此只能從其他方案想辦法了。

獲取範例上的熱點程序：

curl -XGET /_nodes/xx.xx.xx.xx/hot_threads?pretty -s

範例A的CPU使用率高一般導致這個情況原因一個是並行過高導致範例處理不過來，另外一個則是存在任務長時間佔據了程序資源，導致無多餘的資源處理其他的請求。所以我們首先基於這倆個情形進行分析。

（1）是否並行度過高引起範例CPU異常

從之前的分析我們可以得知業務側的流量是沒有出現突增，search.completed的增長只是因為業務重試機制導致的，因此排除並行過高的原因了，那麼剩下的就只有存在長任務的原因了。

（2）是否長任務導致範例CPU異常

根據_cat/tasks檢視當前正在執行的任務，預設會根據時間進行排序，任務running時間越長，那麼就會排到最前面，上面我們得知異常的範例只有A，因此我們可以只匹配範例A上的任務資訊。

curl -XGET '/_cat/tasks?v&s=store' -s | grep A

一般情況下大部分任務都是在秒級以下，若是出現任務執行已超過秒級或者分鐘級的任務，那麼這個肯定就是屬於長任務。

（3）什麼長任務比較多

根據介面可以看得到耗時較長的都是relocate任務，這個時候使用檢視介面/_cat/shards檢視分片遷移資訊，並且並行任務還很多，持續時間相較於其他任務來說很長。

curl -XGET '/_cat/shards?v&s=store' -s | grep A

由於當時是優先恢復業務，因此沒有截圖，最後只能從監控獲取得到這個時間是有進行relocate分片的遷移操作：

es.node.indices.segment.count：範例級別segment的個數。
es.cluster.relocatingshards：叢集級別正在進行relocate的分片數量。

（4）什麼原因導致了分片遷移變多

根據日常的運維，一般出現分片遷移的情況有：

範例故障。
人工進行分片遷移或者節點剔除。
磁碟使用率達到了高水平位。

根據後續的定位，可以排除範例故障和人工操作這倆項，那麼進一步定位是否由於磁碟高水平位導致的。

檢視範例級別的監控：

檢視master的紀錄檔：

[xxxx-xx-xxT19:43:28,389][WARN ][o.e.c.r.a.DiskThresholdMonitor] [master] high disk watermark [90%] exceeded on [ZcphiDnnStCYQXqnc_3Exg][A][/xxxx/data/nodes/0] free: xxxgb[9.9%], shards will be relocated away from this node
[xxxx-xx-xxT19:43:28,389][INFO ][o.e.c.r.a.DiskThresholdMonitor] [$B] rerouting shards: [high disk watermark exceeded on one or more nodes]

根據監控和紀錄檔能夠進一步確認是磁碟使用率達到了高水平位從而導致的遷移問題。

（5）確認引起磁碟上漲的範例

通過內部監控平臺的DB監控，檢視機器級別上所有範例的監控指標

es.instance.data_size：

通過監控我們分析可以得到淺黃色、深藍色、淺綠色三個範例是存在較大的磁碟資料量大小的增長情況，可以比較明顯匯出磁碟增長到90%的原因是淺黃色線代表的範例導致的原因。

2.3 根因分析

針對範例A磁碟波動情況進行分析：

檢視這個監控圖，你會發現存在異常：

磁碟資料量的下降和上升並不是一個緩慢的曲線。
2023-02-07 19:20左右也發生過磁碟下降的情況。

出現磁碟的下降和趨勢一次性比較多的情況，根據以往的經驗存在：

大規模的刷資料。
relocate的分片是一個大分片。
relocate並行數比較大。

第一個排除了，大規模的刷資料只會導致資料上升，並不會出現資料下降的情況，因此要麼就是大分片，要麼就是並行較大。

檢視是否存在大分片：

# curl -XGET '/_cat/shards?v&s=store' -s | tail
index_name                            4     r      STARTED 10366880  23.2gb
index_name                            4     p      STARTED 10366880  23.2gb
index_name                            0     r      STARTED 10366301  23.2gb
index_name                            0     p      STARTED 10366301  23.2gb
index_name                            3     p      STARTED 10347791  23.3gb
index_name                            3     r      STARTED 10347791  23.3gb
index_name                            2     p      STARTED 10342674  23.3gb
index_name                            2     r      STARTED 10342674  23.3gb
index_name                            1     r      STARTED 10328206  23.4gb
index_name                            1     p      STARTED 10328206  23.4gb

檢視是否存在重定向並行數較大：

# curl -XGET '/_cluster/settings?pretty'
{
... ...
  "transient" : {
    "cluster" : {
      "routing" : {
        "allocation" : {
          "node_concurrent_recoveries" : "5",
          "enable" : "all"
        }
      }
    }
  }
}

發現引數cluster.allocation.node_concurrent_recoveries設定成了5，我們看下官方針對這個引數的解釋：https://www.elastic.co/guide/en/elasticsearch/reference/6.3/shards-allocation.html

大致意思是同一個時間允許多個的分片可以並行的進行relocate或者recovery，我們就按照較大的分片數量20G*5，差不多就是100G左右，這個就解釋了為什麼data_size的增長和下降短時間內非常大的資料量的原因了。

到目前為止，我們能夠確認的是因為分片遷移的問題消耗了範例A很大的CPU資源，從而導致範例A的CPU指標非常的高。

三、解決方案

基於上面的分析，我們假設由於範例A的異常導致叢集整的異常；基於這種假設，我們嘗試將範例A剔除叢集，觀察叢集和業務的請求是否能夠恢復。

3.1 猜想驗證

將範例的分片遷移到其他的範例上，執行以下命令之後，可以明顯的發現範例上的請求基本上下降為零了，並且業務反饋超時也在逐步的減少，基於這個情況驗證了我們的猜想，是範例A的異常導致了業務的請求超時的情況。

curl -XPUT  /_cluster/settings?pretty -H 'Content-Type:application/json' -d '{
    "transient":{
        "cluster.routing.allocation.exclude._ip": "xx.xx.xx.xx"
    }
}'

3.2 根本解決

猜想驗證確認之後，那我們現在基於範例A的CPU的異常結果進行相關的優化：

修改引數cluster.routing.allocation.node_concurrent_recoveries

該引數預設值是2，一般是不建議修改這個引數，但是有需要快速遷移要求的業務可以動態修改這個引數，建議不要太激進，開啟之後需要觀察範例、機器級別的CPU、磁碟IO、網路IO的情況。

修改引數cluster.routing.use_adaptive_replica_selection

開啟該引數之後，業務針對分片的讀取會根據請求的耗時的響應情況選擇下次請求是選擇主分片還是副分片。
6.3.2版本預設是關閉了該引數，業務預設會輪詢查詢主副分片，這在部分範例異常的情況會影響叢集的整體效能。針對生產環境、單機多範例混合部署的情況下，建議開啟該引數，對叢集的效能有一定的提高。
7.x的版本預設是開啟了這個引數。

curl -XPUT  /_cluster/settings?pretty -H 'Content-Type:application/json' -d '{
    "transient":{
        "cluster.routing.allocation.node_concurrent_recoveries": 2,
        "cluster.routing.use_adaptive_replica_selection":true   
    }
}'

直接擴容或者遷移範例也是比較合適的。

四、總結

在本次故障，是由於叢集引數設定不正確，導致叢集的一個範例出現異常從而導致了業務的請求異常。但是在我們在進行故障分析的時候，不能僅僅只是侷限於資料庫側，需要基於整個請求鏈路的分析，從業務側、網路、資料庫三個方面進行分析：

業務側：需確認業務的所在的機器的CPU、網路和磁碟IO、記憶體是否使用正常，是否有出現資源爭用的情況；確認JVM的gc情況，確認是否是因為gc阻塞導致了請求阻塞；確認流量是否有出現增長，導致Elasticsearch的瓶頸。
網路側：需確認是否有網路抖動的情況。
資料庫側：確認是Elasticsearch是否是基於叢集級別還是基於範例級別的異常；確認叢集的整體請求量是否有出現突增的情況；確認異常的範例的機器是否有出現CPU、網路和磁碟IO、記憶體的使用情況。

確認哪方面的具體故障之後，就可以進一步的分析導致故障的原因。

引數控制：

Elasticsearch本身也有一些引數在磁碟使用率達到一定的情況下來控制分片的分配策略，預設該策略是開啟的，其中比較重要的引數：

cluster.routing.allocation.disk.threshold_enabled：預設值是true，開啟磁碟分分配決策程式。
cluster.routing.allocation.disk.watermark.low：預設值85%，磁碟使用低水位線。達到該水位線之後，叢集預設不會將分片分配達到該水平線的機器的範例上，但是新建立的索引的主分片可以被分配上去，副分片則不允許。
cluster.routing.allocation.disk.watermark.high：預設值90%，磁碟使用高水位線。達到該水位線之後，叢集會觸發分片的遷移操作，將磁碟使用率超過90%範例上的分片遷移到其他分片上。
cluster.routing.allocation.disk.watermark.high：預設值95%。磁碟使用率超過95%之後，叢集會設定所有的索引開啟引數read_only_allow_delete，此時索引是隻允許search和delete請求。

補充：

一旦一臺機器上的磁碟使用率超過了90%，那麼這臺機器上所有的ES範例所在的叢集都會發起分片的遷移操作，那麼同一時間發起並行的最大可能是：ES範例數*cluster.routing.allocation.node_concurrent_recoveries，這個也會導致機器的CPU、IO等機器資源進一步被消耗，從而所在的範例效能會更差，從而導致路由到機器上範例的分片的效能會更差。

一旦一臺機器上磁碟使用率超過95%，那麼這臺機器上所有的範例所在的叢集都會開啟叢集級別的引數read_only_allow_delete，此時不僅僅是一個叢集，而是一個或者多個叢集都無法寫入，只能進行search和delete。

線上ES叢集引數設定引起的業務異常案例分析