排查 Go 开发的 HttpClient 读取 Body 超时

兼职招募 | 51CTO社区编辑添盟指南

记一次go httpclient [读取反响Body超时]的排查过程。

今年度解锁的第一个技能。

1故障现场

本人负责的主备集群,发出的 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 超时阈值。

这边有必要穿插 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。

写入和读取互不作梗,但是时空有重叠。

因而[读取 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前后添时兴间日志。

$ go run main.go 2022/01/07 20:21:46 最先乞求: 2022-01-07 20:21:46.010 2022/01/07 20:21:47 服务端处理终结: 2022-01-07 20:21:47.010 2022/01/07 20:21:52 客户端读取终结: 2022-01-07 20:21:52.010 2022/01/07 20:21:52 response body length: 50575756 

能够望出,当读取大的反响体时候,客户端iotil.ReadAll的耗时并不算幼,这块必要开发人员偏重。

吾们甚至能够iotil.ReadAll之前time.Sleep(xxx), 就能轻盈模拟出生产环境的读取 Body 超时。

4吾的收获

1.Nginx Access Log 的时间含义

2.go 的 HttpClient Timeout 包含了连接、乞求、读取 Body 的耗时

3.始末对[读取 Body 超时变态]的分析,吾梳理了端到端的乞求耗时、客户端的走为耗时的时空有关, 这个至关主要。

引用链接

[1] nginx access log: https://docs.nginx.com/nginx/admin-guide/monitoring/logging/

[2] 替换iotil.ReadAll的方案: https://stackoverflow.com/questions/52539695/alternative-to-ioutil-readall-in-go

【编辑选举】

鸿蒙官方战略配相符共建——HarmonyOS技术社区 Dubbo为什么用Go重写? 项现在实战:行使 Fiber + Gorm 构建 Rest API 实时进化 万象纷呈:一文回顾声网Agora的2021 全栈 django restful vue2 elementui 完善幼福商城注册之短信发送 Go说话行使Gin框架开发邮件告警接口功能