排查 Go 開發(fā)的 HttpClient 讀取 Body 超時

作者：有態(tài)度的馬甲 2022-01-09 17:38:32

本人負(fù)責(zé)的主備集群,發(fā)出的 HttpClient 請求有 30%概率超時，報context deadline exceeded (Client.Timeout or context cancellation while reading body) 異常

記一次go httpclient [讀取響應(yīng)Body超時]的排查過程。

今年度解鎖的第一個技能。

1故障現(xiàn)場

本人負(fù)責(zé)的主備集群,發(fā)出的 HttpClient 請求有 30%概率超時，報context deadline exceeded (Client.Timeout or context cancellation while reading body) 異常

Kibana 顯示 Nginx 處理請求的耗時request_time在[5s-1min]區(qū)間波動， upstream_response_time在 2s 級別。

所以我們認(rèn)定是 Nginx 向客戶端回傳 50M 的數(shù)據(jù)，發(fā)生了網(wǎng)絡(luò)延遲。于是將 HttpClient Timeout 從 30s 調(diào)整到 60s，上線之后明顯改善。

But 昨天又出現(xiàn)了一次同樣的超時異常

time="2022-01-05T22:28:59+08:00" .... 
time="2022-01-05T22:30:02+08:00" level=error msg="service Run error" error="region: sz,first load self allIns error:context deadline exceeded (Client.Timeout or context cancellation while reading body)"

2線下復(fù)盤

go的HttpClient Timeout包括連接、重定向(如果有)、從Response Body讀取的時間，內(nèi)置定時器會在Get，Head、Post、Do 方法之后繼續(xù)運(yùn)行，直到讀取完Response.Body.

Timeout specifies a time limit for requests made by this Client. The timeout includes connection time, any redirects, and reading the response body. The timer remains running after Get, Head, Post, or Do return and will interrupt reading of the Response.Body.

Kibana 顯示 Nginx 處理請求的耗時request_time才 32s, 遠(yuǎn)不到我們對于 Http 客戶端設(shè)置的 60s 超時閾值。

這里有必要穿插 Nginx Access Log 的幾個背景點(diǎn)

1.Nginx 寫日志的時間根據(jù)nginx access log[1]官方，NGINX writes information about client requests in the access log right after the request is processed. 也就是說 Nginx 是在端到端請求被處理完之后才寫入日志。

2.Nginx Request_Time upstream_response_time

$upstream_response_time – The time between establishing a connection and receiving the last byte of the response body from the upstream server

從 Nginx 向后端建立連接開始到接受完數(shù)據(jù)然后關(guān)閉連接為止的時間

$request_time– The total time spent processing a request

Nginx 從接受用戶請求的第一個字節(jié)到發(fā)送完響應(yīng)數(shù)據(jù)的時間

從目前的信息看，Nginx 從接受請求到發(fā)送完響應(yīng)流，總共耗時 32s。那剩下的 28s，是在哪里消耗的?

3三省吾身

這是我抽離的 HttpClient 的實(shí)踐，常規(guī)的不能再常規(guī)。

package main 
 
import ( 
    "bytes" 
    "encoding/json" 
    "io/ioutil" 
    "log" 
    "net/http" 
    "time" 
) 
 
func main() { 
      c := &http.Client{Timeout: 10 * time.Second} 
      body := sendRequest(c, http.MethodPost) 
      log.Println("response body length:", len(body)) 
} 
 
func sendRequest(client *http.Client, method string) []byte { 
      endpoint := "http://mdb.qa.17usoft.com/table/instance?method=batch_query" 
      expr := "idc in (logicidc_hd1,logicidc_hd2,officeidc_hd1)" 
      jsonData, err := json.Marshal([]string{expr}) 
      response, err := client.Post(endpoint, "application/json", bytes.NewBuffer(jsonData)) 
      if err != nil { 
          log.Fatalf("Error sending request to api endpoint, %+v", err) 
      } 
      defer response.Body.Close() 
      body, err := ioutil.ReadAll(response.Body) 
      if err != nil { 
          log.Fatalf("Couldn't parse response body, %+v", err) 
      } 
      return body 
}

核心就兩個動作

調(diào)用Get、Post、Do方法發(fā)起 Http 請求，如果無報錯，則表示服務(wù)端已經(jīng)處理了請求
iotil.ReadAll表示客戶端準(zhǔn)備從網(wǎng)卡讀取 Response Body (流式數(shù)據(jù)), 超時異常正是從這里爆出來的

報錯內(nèi)容："Client.Timeout or context cancellation while reading body" 讀取 Response Body 超時，

潛臺詞是：服務(wù)器已經(jīng)處理了請求，并且開始向客戶端網(wǎng)卡寫入數(shù)據(jù)。

根據(jù)我有限的網(wǎng)絡(luò)原理/計算機(jī)原理，與此同時，客戶端會異步從網(wǎng)卡讀取 Response Body。

寫入和讀取互不干擾，但是時空有重疊。

所以[讀取 Body 超時]位于圖中的紅框區(qū)域，這就有點(diǎn)意思了。

之前我們有 30%概率[讀取 Body 超時]，確實(shí)是因?yàn)?Nginx 回傳 50M 數(shù)據(jù)超時，這在 Nginx request_time 上能體現(xiàn)。
本次 Nginx 顯示 request_time=32s, 卻再次超時，推斷 Nginx 已經(jīng)寫完數(shù)據(jù)，而客戶端還沒有讀取完 Body。

至于為什么沒讀取完，這就得吐槽iotil.ReadAll的性能了。客戶端使用 iotil.ReadAll 讀取大的響應(yīng)體，會不斷申請內(nèi)存(源碼顯示會從 512B->50M)，耗時較長，性能較差、并且有內(nèi)存泄漏的風(fēng)險。客戶端機(jī)器稍有差池，可能就會導(dǎo)致讀大Body超時，下一篇我會講解針對大的響應(yīng)體替換iotil.ReadAll的方案[2]。

為了模擬這個偶發(fā)的情況，我們可在Post、iotil.ReadAll前后加入時間日志。

$ go run main.go 
2022/01/07 20:21:46 開始請求: 2022-01-07 20:21:46.010 
2022/01/07 20:21:47 服務(wù)端處理結(jié)束: 2022-01-07 20:21:47.010 
2022/01/07 20:21:52 客戶端讀取結(jié)束: 2022-01-07 20:21:52.010 
2022/01/07 20:21:52 response body length: 50575756

可以看出，當(dāng)讀取大的響應(yīng)體時候，客戶端iotil.ReadAll的耗時并不算小，這塊需要開發(fā)人員重視。

我們甚至可以iotil.ReadAll之前time.Sleep(xxx)，就能輕松模擬出生產(chǎn)環(huán)境的讀取 Body 超時。