欧美精品v国产精品v,一卡2卡3卡4卡5卡视频在线,蜜臀国产在线

排查 Go 開發的 HttpClient 讀取 Body 超時

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

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

1故障現場

排查 Go 開發的 HttpClient 讀取 Body 超時

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

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

所以我們認定是 Nginx 向客戶端回傳 50M 的數據，發生了網絡延遲。于是將 HttpClient Timeout 從 30s 調整到 60s，上線之后明顯改善。

But 昨天又出現了一次同樣的超時異常

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線下復盤

go的HttpClient Timeout包括連接、重定向(如果有)、從Response Body讀取的時間，內置定時器會在Get，Head、Post、Do 方法之后繼續運行，直到讀取完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, 遠不到我們對于 Http 客戶端設置的 60s 超時閾值。

排查 Go 開發的 HttpClient 讀取 Body 超時

這里有必要穿插 Nginx Access Log 的幾個背景點

1.Nginx 寫日志的時間根據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 向后端建立連接開始到接受完數據然后關閉連接為止的時間

$request_time– The total time spent processing a request

Nginx 從接受用戶請求的第一個字節到發送完響應數據的時間

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

3三省吾身

這是我抽離的 HttpClient 的實踐，常規的不能再常規。

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
}

核心就兩個動作

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

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

潛臺詞是：服務器已經處理了請求，并且開始向客戶端網卡寫入數據。

根據我有限的網絡原理/計算機原理，與此同時，客戶端會異步從網卡讀取 Response Body。

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

排查 Go 開發的 HttpClient 讀取 Body 超時

所以[讀取 Body 超時]位于圖中的紅框區域，這就有點意思了。

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

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

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