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。

請求已經到服務端了還超時的緣由，多是：

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。