七叶笔记 » golang编程 » Go 中 http 超时问题的排查

Go 中 http 超时问题的排查

分类: golang编程 | 浏览: 898

背景

最新有同事反馈，服务间有调用超时的现象，在业务高峰期发生的概率和次数比较高。从日志中调用关系来看，有2个调用链经常发生超时问题。

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

问题2: A 服务使用一个轻量级 http-sdk(内部 http2.0) 发送请求到 C 服务超时。

Golang 给出的报错信息时： 

Post  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 并发也会创建新连接。继续追查有设置这个变量的地方： 

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。

真相

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

简化来说：

  1. 调用方和服务方使用 http1.1 升级到 http2 的模式进行通讯
  2. 服务方 http2Serve r限制单连接并发数是 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。

相关文章