Go 中 http 超时问题的排查 _Go

文章插图

作者：蘑菇先生
出处：http://mushroom.cnblogs.com/

背景最新有同事反馈，服务间有调用超时的现象，在业务高峰期发生的概率和次数比较高。从日志中调用关系来看，有2个调用链经常发生超时问题。
问题1：A 服务使用 http1.1 发送请求到 B 服务超时。
问题2: A 服务使用一个轻量级 http-sdk(内部 http2.0) 发送请求到 C 服务超时。
Golang 给出的报错信息时：
Post http://host/v1/xxxx: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)通知日志追踪 ID 来排查，发现有的请求还没到服务方就已经超时。有些已经到服务方了，但也超时。这里先排查的是问题2 ，下面是过程。
排查推测
调用方设置的 http 请求超时时间是1s 。请求已经到服务端了还超时的原因，可能是：

服务方响应慢。通过日志排查确实有部分存在。
客户端调用花了990ms ，到服务端只剩 10ms ，这个肯定会超时。

请求没到服务端超时的原因，可能是：

golang CPU 调度不过来。通过 cpu 监控排除这个可能性
golang 网络库原因。重点排查

排查方法：
本地写个测试程序， 1000 并发调用测试环境的 C 服务:
n := 1000var waitGroutp = sync.WaitGroup{}waitGroutp.Add(n)for i := 0; i < n; i++ { go func(x int) { httpSDK.Request() }}waitGroutp.Wait()
报错：
too many open files // 这个错误是笔者本机ulimit太小的原因，可忽略net/http: request canceled (Client.Timeout exceeded while awaiting headers)并发数量调整到 500 继续测试，还是报同样的错误。

连接超时
本地如果能重现的问题，一般来说比较好查些。
开始跟 golang 的源码，下面是创建 httpClient 的代码，这个 httpClient 是全局复用的。
func createHttpClient(host string, tlsArg *TLSConfig) (*http.Client, error) { httpClient := &http.Client{ Timeout: time.Second, } tlsConfig := &tls.Config{InsecureSkipVerify: true} transport := &http.Transport{ TLSClientConfig: tlsConfig, MaxIdleConnsPerHost: 20, } http2.ConfigureTransport(transport) return httpClient, nil}// 使用httpClienthttpClient.Do(req)跳到 net/http/client.go 的 do 方法
func (c *Client) do(req *Request) (retres *Response, reterr error) { if resp, didTimeout, err = c.send(req, deadline); err != nil { }}继续进 send 方法，实际发送请求是通过 RoundTrip 函数。
func send(ireq *Request, rt RoundTripper, deadline time.Time) (resp *Response, didTimeout func() bool, err error) { rt.RoundTrip(req) }send 函数接收的 rt 参数是个 inteface ，所以要从 http.Transport 进到 RoundTrip 函数。其中 log.Println("getConn time", time.Now().Sub(start), x) 是笔者添加的日志，为了验证创建连接耗时。
var n int// roundTrip implements a RoundTripper over HTTP.func (t *Transport) roundTrip(req *Request) (*Response, error) { // 检查是否有注册http2 ，有的话直接使用http2的RoundTrip if t.useRegisteredProtocol(req) { altProto, _ := t.altProto.Load().(map[string]RoundTripper) if altRT := altProto[scheme]; altRT != nil { resp, err := altRT.RoundTrip(req) if err != ErrSkipAltProtocol { return resp, err } } } for { //n++ // start := time.Now() pconn, err := t.getConn(treq, cm) // log.Println("getConn time", time.Now().Sub(start), x) if err != nil { t.setReqCanceler(req, nil) req.closeBody() return nil, err } }}结论：加了日志跑下来，确实有大量的 getConn time 超时。

疑问
这里有2个疑问：

为什么 Http2 没复用连接，反而会创建大量连接？
创建连接为什么会越来越慢？

继续跟 getConn 源码, getConn 第一步会先获取空闲连接，因为这里用的是http2 ，可以不用管它。追加耗时日志，确认是 dialConn 耗时的。
func (t *Transport) getConn(treq *transportRequest, cm connectMethod) (*persistConn, error) { if pc, idleSince := t.getIdleConn(cm); pc != nil { } //n++ go func(x int) { // start := time.Now() // defer func(x int) { // log.Println("getConn dialConn time", time.Now().Sub(start), x) // }(n) pc, err := t.dialConn(ctx, cm) dialc <- dialRes{pc, err} }(n)}继续跟 dialConn 函数，里面有2个比较耗时的地方：