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 := 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个疑问:
为什么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.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。
真相
上面的步骤,更多的是为了记录排查过程和源码中的关键点,方便以后类似问题有个参考。
简化来说:
- 调用方和服务方使用http1.1升级到http2的模式进行通讯
- 服务方http2server限制单连接并发数是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。