ES客戶端請求超時問題排查
一、現象
生產的3臺ES用Nginx做代理，客戶端->Nginx->ES都是長連線。ES客戶端每天會有30條左右的超時日誌，這是客戶端設定了60s請求超時主動報錯引起的，錯誤資訊如下（搜尋、按ID獲取、建立索引都會出現超時）：
java.net.SocketTimeoutException: 60,000 milliseconds timeout on connection http-outgoing-922 [ACTIVE] at org.elasticsearch.client.RestClient.extractAndWrapCause(RestClient.java:808) at org.elasticsearch.client.RestClient.performRequest(RestClient.java:248) at org.elasticsearch.client.RestClient.performRequest(RestClient.java:235) at org.elasticsearch.client.RestHighLevelClient.internalPerformRequest(RestHighLevelClient.java:1514) at org.elasticsearch.client.RestHighLevelClient.performRequest(RestHighLevelClient.java:1484) at org.elasticsearch.client.RestHighLevelClient.performRequestAndParseEntity(RestHighLevelClient.java:1454) at org.elasticsearch.client.RestHighLevelClient.update(RestHighLevelClient.java:921)
客戶端設定了socketTimeout為60秒，所以可以肯定的是請求長時間無資料返回導致報錯。Nginx裡的錯誤日誌如下：
2021/05/20 13:26:58 [warn] 491406#491406: *94078113 an upstream response is buffered to a temporary file /data/openresty/nginx/proxy_temp/1/65/0000049651 while reading upstream, client: 10.81.127.209, server: 10.30.223.84, request: "POST /spprjm_customer/_search HTTP/1.1", upstream: "http://10.29.56.90:39200/spprjm_customer/_search", host: "10.30.223.84:86" 2021/05/20 13:26:59 [info] 491406#491406: *94076470 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while connecting to upstream, client: 10.45.179.90, server: 10.30.223.84, request: "POST /enterprise_v1/_search HTTP/1.1", upstream: "http://10.30.222.121:39200/enterprise_v1/_search", host: "10.30.223.84:86" 10.45.182.231 - - [21/Jun/2021:16:41:01 +0800] "POST /person_search_user_v1/_search HTTP/1.1" "/person_search_user_v1/_search" "60.052" "-" 499 0 "-" "Apache-HttpAsyncClient/4.1.4 (Java/1.8.0_144)"
這裡的epoll_wait()錯誤與業務裡的超時異常是一一對應的，就是說客戶端等待60s後提前斷開了長連線，於是Nginx也斷開了與上游代理的長連線，最後響應499錯誤碼。
二、排查問題
看到這些錯誤，於是在網路上尋找答案，下邊列舉幾個感覺有價值的資訊：
- 關於 Nginx 日誌錯誤碼 499的問題
- 談nginx中的keepalive、Openresty主動關閉連線與KeepAlive，這兩個講解的是關於長連線請求的問題
- Tcp keepalive 引發的 Connection reset by peer 異常、stackoverflow裡關於ES客戶端超時的提問，這兩個講解的是防火牆超時比tcp超時早導致的網路丟包問題
- linux下TCP引數設定詳解、Nginx官方文件關於超時的設定
- 如何防止防火牆導致的資料庫空閒連線斷開問題，我們的客戶端是90s長連線，用的時候會處理連線狀態，不會報連線斷開錯誤
通過排查伺服器配置net.ipv4.tcp_keepalive_time = 1200可以排除是防火牆連線超時過早導致網路不通，一般防火牆連線超時是1小時（我沒有找到任何教程對於這個時間的配置，但在 Iptables Default connections 裡看到預設是600s超時，由於能力有限沒辦法得知伺服器裡的真實數值），TCP連線在1200s後會有多次探測，所以應該不是防火牆把連線過早斷開的問題。
我把問題指向了ES服務，經過kibana裡的監控得知，近期的請求延遲並不高，但是與客戶端超時有一致的延遲突起，說明與ES還是有一定關係的，我找到一篇文章介紹了監控引數，可以認為這裡的監控值取的是平均值。那就把ES的慢請求日誌開啟，看看到底有多大的延遲，配置如下：
PUT /_all/_settings?preserve_existing=true
{
"index.indexing.slowlog.level" : "info",
"index.indexing.slowlog.source" : "1000",
"index.indexing.slowlog.threshold.index.info" : "100ms",
"index.search.slowlog.threshold.fetch.info" : "100ms",
"index.search.slowlog.threshold.query.info" : "100ms"
}
經過幾個小時的等待，生產最終有業務報超時了，然後排查ES慢日誌，得到的最大延遲卻只有1s左右（也有可能這個請求根本沒打日誌，這裡還需要認真排查確認），看起來並不是ES響應慢的問題，到這裡我沒有了思路。
三、在測試環境復現問題
我本機開啟多個執行緒對ES發起查詢（客戶端連線數配置充足，不然會停頓在獲取連線的地方，反而復現不出請求超時），線上程數為50的時候下行頻寬達到了100%，執行緒開到200時就開始頻繁出現10s超時。使用jvisualvm檢視執行緒狀態發現，有大量執行緒長時間被掛起（頻寬不夠導致IO等待），執行緒喚醒後出現超時異常，但是Nginx的錯誤日誌與生產的並不一樣，因為生產只有epoll_wait()一種錯誤，測試環境卻出現瞭如下幾種錯誤，只有我強制關閉程式時才會出現與生產一致的錯誤：
2021/06/21 15:07:52 [info] 14749#0: *58644745 recv() failed (104: Connection reset by peer) while sending to client, client: 172.16.9.119, server: 172.16.1.78, request: "POST /prep_statistics_service_process_detail/_search HTTP/1.1", upstream: "http://172.16.1.78:9203/prep_statistics_service_process_detail/_search", host: "172.16.1.78:86"
2021/06/21 20:01:13 [info] 14749#0: *61424251 writev() failed (104: Connection reset by peer) while sending to client, client: 172.16.20.14, server: 172.16.1.78, request: "POST /prep_srms_service_record_group/_search HTTP/1.1", upstream: "http://172.16.1.78:9201/prep_srms_service_record_group/_search", host: "172.16.1.78:86"
2021/06/21 15:07:52 [info] 14749#0: *58658403 client 172.16.9.119 closed keepalive connection (104: Connection reset by peer)
經過思考，我認為可能是由於客戶端執行緒掛起，而這時請求在Nginx這裡是不停的讀寫的，客戶端超時後，Nginx這裡即有可能在讀資料也有可能在寫資料，最終出現這些網路錯誤。
於是我把測試程式放在網路更好的虛擬器上執行，但是CPU卻在200執行緒時就佔滿了，最終500個執行緒只使用了50%的頻寬，這時出現了我期待的5s超時。通過jvisualvm分析發現也是由於執行緒掛起導致，這次是CPU競爭導致的長時間等待。
於是我開始定位業務伺服器的負載情況，通過觀察歷史監控資料得知GC停頓並不大，CPU負載也不高，出入頻寬也才使用10%。分析到這裡我沒有了思路。不過今天測試組在做生產的搜尋壓測，導致近4個小時有100左右的業務60s請求超時日誌，這又讓我開始懷疑是ES負載高的問題。
總結：
- Nginx的 proxy_next_upstream 預設配置是：error timeout
- 生產配置的 proxy_connect_timeout 為3600秒是不合理的（客戶端60s就會主動報錯），這樣就沒法利用Nginx的重試機制
- 合理的配置應該設定: proxy_connect_timeout 10 快速觸發超時並重連下一臺機器，這樣ES客戶端很大機率不用等待60s就可正常通訊