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

vivo網際網路技術發表於2023-11-23

作者：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。

相關文章