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。

请求已经到服务端了还超时的原因，可能是：

1. 服务方响应慢。 通过日志排查确实有部分存在。

2. 客户端调用花了990ms，到服务端只剩10ms，这个肯定会超时。

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

1. golang cpu调度不过来。通过cpu监控排除这个可能性

2. golang 网络库原因。重点排查

排查方法：

本地写个测试程序，1000并发调用测试环境的c服务:

n := 1000
var 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
}
// 使用httpclient
httpclient.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个疑问：

1. 为什么http2没复用连接，反而会创建大量连接？

2. 创建连接为什么会越来越慢？

继续跟 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个比较耗时的地方：

1. 连接建立，三次握手。

2. tls握手的耗时，见下面http2章节的dialconn源码。

分别在dialconn函数中 t.dial 和 addtls 的位置追加日志。

可以看到，三次握手的连接还是比较稳定的，后面连接的在tls握手耗时上面，耗费将近1s。

2019/10/23 14:51:41 dialtime 39.511194ms https.handshake 1.059698795s
2019/10/23 14:51:41 dialtime 23.270069ms https.handshake 1.064738698s
2019/10/23 14:51:41 dialtime 24.854861ms https.handshake 1.0405369s
2019/10/23 14:51:41 dialtime 31.345886ms https.handshake 1.076014428s
2019/10/23 14:51:41 dialtime 26.767644ms https.handshake 1.084155891s
2019/10/23 14:51:41 dialtime 22.176858ms https.handshake 1.064704515s
2019/10/23 14:51:41 dialtime 26.871087ms https.handshake 1.084666172s
2019/10/23 14:51:41 dialtime 33.718771ms https.handshake 1.084348815s
2019/10/23 14:51:41 dialtime 20.648895ms https.handshake 1.094335678s
2019/10/23 14:51:41 dialtime 24.388066ms https.handshake 1.084797011s
2019/10/23 14:51:41 dialtime 34.142535ms https.handshake 1.092597021s
2019/10/23 14:51:41 dialtime 24.737611ms https.handshake 1.187676462s
2019/10/23 14:51:41 dialtime 24.753335ms https.handshake 1.161623397s
2019/10/23 14:51:41 dialtime 26.290747ms https.handshake 1.173780655s
2019/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 := 1000
var 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并发也会创建新连接。继续追查有设置这个变量的地方：

func (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。

真相

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

简化来说：

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

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

重试

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。