记录一个gohttpclient[readresponseBodytimeout]排查过程。今年解锁的第一个技能。1、故障现场我负责的主备集群中，发送的HttpClient请求有30%的概率超时，上报contextdeadlineexceeded(Client.Timeoutorcontextcancellationwhilereadingbody)异常.Kibana显示Nginx处理请求的耗时request_time在[5s-1min]范围内波动，upstream_response_time在2s级别。所以我们判断是Nginx给客户端返回了50M的数据，出现了网络延迟。于是将HttpClientTimeout由30s调整为60s，上线后明显改善。但是昨天又出现了同样的超时异常time="2022-01-05T22:28:59+08:00"...time="2022-01-05T22:30:02+08:00"level=errormsg="serviceRunerror"error="region:sz,firstloadselfallInserror:contextdeadlineexceeded(Client.Timeoutorcontextcancellationwhilereadingbody)"2离线重播Go的HttpClientTimeout包括连接、重定向（如果有）、从ResponseBody读取的时间、内置计时服务器会继续运行在Get、Head、Post和Do方法之后，直到Response.Body.Timeout指定此客户端发出的请求的时间限制。超时包括连接时间、任何重定向和读取响应正文。定时器在Get、Head、Post、Do返回后继续运行，会中断读取Response.Body。Kibana显示Nginx处理请求的耗时request_time只有32s，远小于60s超时我们为Http客户端设置的阈值。这里有必要穿插一下NginxAccessLog的几个背景点1.Nginx写日志的时间根据nginx官方的accesslog[1]，NGINX在处理完请求后，会在accesslog中写入客户端请求的信息。也就是说，Nginx是在端到端的请求处理完之后才写入日志的。2.NginxRequest_Timeupstream_response_time$upstream_response_time–从Nginx与后端建立连接到接受数据再关闭连接，从建立连接到收到上游服务器响应体最后一个字节的时间。$request_time–处理一个请求的总时间Nginx从接受用户请求的第一个字节到从当前信息发送响应数据一共需要32秒。剩下的28s消耗到哪里去了？3、对自己的三个反思这是我摘抄的HttpClient的做法，常规的不能再常规了。packagemainimport("bytes""encoding/json""io/ioutil""log""net/http""time")funcmain(){c:=&http.Client{Timeout:10*time.Second}body:=sendRequest(c,http.MethodPost)log.Println("responsebodylength:",len(body))}funcsendRequest(client*http.Client,methodstring)[]byte{endpoint:="http://mdb.qa.17usoft.com/table/instance?method=batch_query"expr:="idcin(logicidc_hd1,logicidc_hd2,officeidc_hd1)"jsonData,err:=json.Marshal([]string{expr})response,err:=client.Post(endpoint,"application/json",bytes.NewBuffer(jsonData))iferr!=nil{log.Fatalf("Errorsendingrequesttoapiendpoint,%+v",err)}deferresponse.Body.Close()body,err:=ioutil.ReadAll(响应.Body)iferr!=nil{log.Fatalf("Couldn'tparseresponsebody,%+v",err)}returnbody}核心调用Get、Post、Do方法发起Http请求这两个动作。如果没有报错，说明服务端已经处理完请求iotil.ReadAll说明客户端准备从网卡读取ResponseBody（流数据），超时异常就是从中突发的错误内容这里："Client.Timeoutorcontextcancellationwhilereadingbody》ReadResponseBody超时，潜台词是：服务端处理完请求，开始向客户端网卡写入数据。根据我有限的网络原理/计算机原理，同时，客户端会异步从网卡中读取ResponseBody，写入和读取互不干扰，只是时间和空间上有重叠，所以【ReadingBodyTimeout】位于红框区域图中，有点意思，之前我们有30%的概率[ReadingBodytimedout]确实是因为Nginx返回50M数据超时，可以在Nginxrequest_time中体现出来，这次Nginx显示request_time=32s，但是超时了再次out。推断是nginx写完了数据，client还在等待。body还没读到客户使用iotil.ReadAll读取一个大的responsebody，会不断申请内存（源码显示会从512B->50M变化），耗时长，性能差，有风险内存泄漏。客户端机器的轻微错误可能会导致读取大体时超时。在下一篇文章中，我将解释如何为大型响应主体替换iotil.ReadAll解决方案[2]。为了模拟这种偶发情况，我们可以在Post和iotil.ReadAll前后添加时间日志。$gorunmain.go2022/01/0720:21:46开始请求：2022-01-0720:21:46.0102022/01/0720:21:47服务器处理结束：2022-01-0720:21:47.0102022/01/0720:21:52客户端读取结束：2022-01-0720:21:52.0102022/01/0720:21:52responsebodylength:50575756可以看出，在读取较大的响应体时，客户端iotil的耗时。ReadAll不小，需要开发者注意。我们甚至可以在iotil.ReadAll之前time.Sleep(xxx)，就可以很方便的在生产环境中模拟readBody超时。4我的收获1.NginxAccessLog的时间意义2.go的HttpClientTimeout包括连接、请求、读取Body的耗时3.通过【读取Body超时异常】的分析，整理了下端到端的耗时请求和客户端的耗时行为之间的时空关系非常重要。参考链接【1】nginx访问日志：https://docs.nginx.com/nginx/admin-guide/monitoring/logging/【2】替换iotil.ReadAll的解决方案：https://stackoverflow.com/questions/52539695/alternative-to-ioutil-readall-in-go
