出處：http://mushroom.cnblogs.com/

背景

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

閱讀更多 Python學習 的文章

關鍵字: 美好，一直在身邊 中央處理器 蘑菇