重试 Go 中 http 超时问题的排查

背景

最新有同事反馈，服务间有调用超时的现象，在业务高峰期发生的概率和次数比较高。从日志中调用关系来看，有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个比较耗时的地方：

连接建立，三次握手。tls握手的耗时，见下面 http2 章节的 dialConn 源码。

分别在 dialConn 函数中 t.dial 和 addTLS 的位置追加日志。可以看到，三次握手的连接还是比较稳定的，后面连接的在 tls 握手耗时上面，耗费将近 1s。

2019/10/23 14:51:41 DialTime 39.511194ms https.Handshake 1.059698795s2019/10/23 14:51:41 DialTime 23.270069ms https.Handshake 1.064738698s2019/10/23 14:51:41 DialTime 24.854861ms https.Handshake 1.0405369s2019/10/23 14:51:41 DialTime 31.345886ms https.Handshake 1.076014428s2019/10/23 14:51:41 DialTime 26.767644ms https.Handshake 1.084155891s2019/10/23 14:51:41 DialTime 22.176858ms https.Handshake 1.064704515s2019/10/23 14:51:41 DialTime 26.871087ms https.Handshake 1.084666172s2019/10/23 14:51:41 DialTime 33.718771ms https.Handshake 1.084348815s2019/10/23 14:51:41 DialTime 20.648895ms https.Handshake 1.094335678s2019/10/23 14:51:41 DialTime 24.388066ms https.Handshake 1.084797011s2019/10/23 14:51:41 DialTime 34.142535ms https.Handshake 1.092597021s2019/10/23 14:51:41 DialTime 24.737611ms https.Handshake 1.187676462s2019/10/23 14:51:41 DialTime 24.753335ms https.Handshake 1.161623397s2019/10/23 14:51:41 DialTime 26.290747ms https.Handshake 1.173780655s2019/10/23 14:51:41 DialTime 28.865961ms https.Handshake 1.178235202s

结论：第二个疑问的答案就是 tls 握手耗时

http2

为什么 Http2 没复用连接，反而会创建大量连接？前面创建 http.Client 时，是通过 http2.ConfigureTransport(transport) 方法，其内部调用了configureTransport ：

func configureTransport(t1 *http.Transport) (*Transport, error) { // 声明一个连接池 // noDialClientConnPool 这里很关键，指明连接不需要dial出来的，而是由http1连接升级而来的 connPool := new(clientConnPool) t2 := &Transport{ ConnPool: noDialClientConnPool{connPool}, t1: t1, } connPool.t = t2// 把http2的RoundTripp的方法注册到，http1上transport的altProto变量上。// 当请求使用http1的roundTrip方法时，检查altProto是否有注册的http2，有的话，则使用// 前面代码的useRegisteredProtocol就是检测方法 if err := registerHTTPSProtocol(t1, noDialH2RoundTripper{t2}); err != nil { return nil, err } // http1.1 升级到http2的后的回调函数，会把连接通过 addConnIfNeeded 函数把连接添加到http2的连接池中 upgradeFn := func(authority string, c *tls.Conn) http.RoundTripper { addr := authorityAddr("https", authority) if used, err := connPool.addConnIfNeeded(addr, t2, c); err != nil { go c.Close() return erringRoundTripper{err} } else if !used { go c.Close() } return t2 } if m := t1.TLSNextProto; len(m) == 0 { t1.TLSNextProto = map[string]func(string, *tls.Conn) http.RoundTripper{ "h2": upgradeFn, } } else { m["h2"] = upgradeFn } return t2, nil}

TLSNextProto 在 http.Transport-> dialConn 中使用。调用upgradeFn函数，返回http2的RoundTripper，赋值给 alt。alt 会在 http.Transport 中 RoundTripper 内部检查调用。

func (t *Transport) dialConn(ctx context.Context, cm connectMethod) (*persistConn, error) { pconn := &persistConn{ t: t, } if cm.scheme() == "https" && t.DialTLS != nil { // 没有自定义DialTLS方法，不会走到这一步 } else { conn, err := t.dial(ctx, "tcp", cm.addr()) if err != nil { return nil, wrapErr(err) } pconn.conn = conn if cm.scheme() == "https" { // addTLS 里进行 tls 握手，也是建立新连接最耗时的地方。 if err = pconn.addTLS(firstTLSHost, trace); err != nil { return nil, wrapErr(err) } } } if s := pconn.tlsState; s != nil && s.NegotiatedProtocolIsMutual && s.NegotiatedProtocol != "" { if next, ok := t.TLSNextProto[s.NegotiatedProtocol]; ok { // next 调用注册的升级函数 return &persistConn{t: t, cacheKey: pconn.cacheKey, alt: next(cm.targetAddr, pconn.conn.(*tls.Conn))}, nil } } return pconn, nil}

结论：

当没有连接时，如果此时来一大波请求，会创建 n 多 http1.1 的连接，进行升级和握手，而 tls 握手随着连接增加而变的非常慢。

解决超时

上面的结论并不能完整解释，复用连接的问题。因为服务正常运行的时候，一直都有请求的，连接是不会断开的，所以除了第一次连接或网络原因断开，正常情况下都应该复用 http2 连接。

通过下面测试，可以复现有 http2 的连接时，还是会创建 N 多新连接：

sdk.Request() // 先请求一次，建立好连接，测试是否一直复用连接。time.Sleep(time.Second)n := 1000var waitGroutp = sync.WaitGroup{}waitGroutp.Add(n)for i := 0; i < n; i++ { go func(x int) { sdk.Request() }}waitGroutp.Wait()

所以还是怀疑 http1.1 升级导致，这次直接改成使用 http2.Transport

httpClient.Transport = &http2.Transport{ TLSClientConfig: tlsConfig,}

改了后，测试发现没有报错了。

为了验证升级模式和直接 http2 模式的区别。这里先回到升级模式中的 addConnIfNeeded 函数中，其会调用 addConnCall 的 run 函数：

func (c *addConnCall) run(t *Transport, key string, tc *tls.Conn) { cc, err := t.NewClientConn(tc)}

run 参数中传入的是 http2 的 transport。整个解释是 http1.1 创建连接后，会把传输层连接，通过 addConnIfNeeded->run->Transport.NewClientConn 构成一个 http2 连接。 因为 http2 和 http1.1 本质都是应用层协议，传输层的连接都是一样的。然后在 newClientConn 连接中加日志。

func (t *Transport) newClientConn(c net.Conn, singleUse bool) (*ClientConn, error) { // log.Println("http2.newClientConn")}

结论：

升级模式下，会打印很多 http2.newClientConn，根据前面的排查这是讲的通的。而单纯 http2 模式下，也会创建新连接，虽然很少。

并发连接数

那 http2 模式下什么情况下会创建新连接呢？

这里看什么情况下http2会调用 newClientConn。回到 clientConnPool 中，dialOnMiss在http2模式下为 true，getStartDialLocked 里会调用 dial->dialClientConn->newClientConn。

func (p *clientConnPool) getClientConn(req *http.Request, addr string, dialOnMiss bool) (*ClientConn, error) { p.mu.Lock() for _, cc := range p.conns[addr] { if st := cc.idleState(); st.canTakeNewRequest { if p.shouldTraceGetConn(st) { traceGetConn(req, addr) } p.mu.Unlock() return cc, nil } } if !dialOnMiss { p.mu.Unlock() return nil, ErrNoCachedConn } traceGetConn(req, addr) call := p.getStartDialLocked(addr) p.mu.Unlock() }

有连接的情况下，canTakeNewRequest 为false，也会创建新连接。看看这个变量是这么得来的：

func (cc *ClientConn) idleStateLocked() (st clientConnIdleState) { if cc.singleUse && cc.nextStreamID > 1 { return } var maxConcurrentOkay bool if cc.t.StrictMaxConcurrentStreams { maxConcurrentOkay = true } else { maxConcurrentOkay = int64(len(cc.streams)+1) < int64(cc.maxConcurrentStreams) } st.canTakeNewRequest = cc.goAway == nil && !cc.closed && !cc.closing && maxConcurrentOkay && int64(cc.nextStreamID)+2*int64(cc.pendingRequests) < math.MaxInt32 // if st.canTakeNewRequest == false { // log.Println("clientConnPool", cc.maxConcurrentStreams, cc.goAway == nil, !cc.closed, !cc.closing, maxConcurrentOkay, int64(cc.nextStreamID)+2*int64(cc.pendingRequests) < math.MaxInt32) // } st.freshConn = cc.nextStreamID == 1 && st.canTakeNewRequest return}

为了查问题，这里加了详细日志。测试下来，发现是 maxConcurrentStreams 超了，canTakeNewRequest 才为 false。在 http2中newClientConn 的初始化配置中, maxConcurrentStreams 默认为 1000：

maxConcurrentStreams: 1000, // "infinite", per spec. 1000 seems good enough.

但实际测下来，发现 500 并发也会创建新连接。继续追查有设置这个变量的地方：

ffunc (rl *clientConnReadLoop) processSettings(f *SettingsFrame) error { case SettingMaxConcurrentStreams: cc.maxConcurrentStreams = s.Val //log.Println("maxConcurrentStreams", s.Val)}

运行测试，发现是服务传过来的配置，值是 250。

结论：服务端限制了单连接并发连接数，超了后就会创建新连接。

服务端限制

在服务端框架中，找到 ListenAndServeTLS 函数，跟下去 ->ServeTLS->Serve->setupHTTP2_Serve->onceSetNextProtoDefaults_Serve->onceSetNextProtoDefaults->http2ConfigureServer。

查到 new(http2Server) 的声明，因为 web 框架即支持 http1.1 也支持 http2，所以没有指定任何 http2 的相关配置，都使用的是默认的。

// Server is an HTTP/2 server.type http2Server struct { // MaxConcurrentStreams optionally specifies the number of // concurrent streams that each client may have open at a // time. This is unrelated to the number of http.Handler goroutines // which may be active globally, which is MaxHandlers. // If zero, MaxConcurrentStreams defaults to at least 100, per // the HTTP/2 spec's recommendations. MaxConcurrentStreams uint32}

从该字段的注释中看出，http2 标准推荐至少为 100，golang 中使用默认变量 http2defaultMaxStreams， 它的值为 250。

真相

上面的步骤，更多的是为了记录排查过程和源码中的关键点，方便以后类似问题有个参考。

简化来说：

调用方和服务方使用 http1.1 升级到 http2 的模式进行通讯服务方 http2Serve r限制单连接并发数是 250当并发超过 250，比如 1000 时，调用方就会并发创建 750 个连接。这些连接的tls握手时间会越来越长。而调用超时只有1s，所以导致大量超时。这些连接有些没到服务方就超时，有些到了但服务方还没来得及处理，调用方就取消连接了，也是超时。

并发量高的情况下，如果有网络断开，也会导致这种情况发送。

重试

A服务使用的轻量级 http-sdk 有一个重试机制，当检测到是一个临时错误时，会重试 2 次。

Temporary() bool // Is the error temporary?

而这个超时错误，就属于临时错误，从而放大了这种情况发生。

解决办法

不是升级模式的 http2 即可。

httpClient.Transport = &http2.Transport{ TLSClientConfig: tlsConfig,}

为什么 http2 不会大量创建连接呢？

这是因为 http2 创建新连接时会加锁，后面的请求解锁后，发现有连接没超过并发数时，直接复用连接即可。所以没有这种情况，这个锁在 clientConnPool.getStartDialLocked 源码中。

问题1

问题1：A服务使用 http1.1 发送请求到 B 服务超时。

问题1 和问题 2 的原因一样，就是高并发来的情况下，会创建大量连接，连接的创建会越来越慢，从而超时。这种情况没有很好的办法解决，推荐使用 http2。如果不能使用 http2，调大 MaxIdleConnsPerHost 参数，可以缓解这种情况。默认 http1.1 给每个 host 只保留 2 个空闲连接，来个1000 并发，就要创建 998 新连接。该调整多少，可以视系统情况调整，比如 50，100。