Go中http超時問題的排查-有解無憂

背景
排查
- 推測
- 連接超時
- 疑問
- http2
- 解決超時
- 并發連接數
- 服務端限制
真相
- 重試
- 解決辦法
- 問題1

背景

最新有同事反饋，服務間有呼叫超時的現象，在業務高峰期發生的概率和次數比較高，從日志中呼叫關系來看，有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，

轉載請註明出處，本文鏈接：https://www.uj5u.com/houduan/67364.html

標籤：Go

上一篇：干貨|Dubbo社區開發者日經驗分享

下一篇：刷14道leetcode的總結