Go中http超時問題的排查

2019 年 10 月 29 日
筆記

背景
排查
真相

背景

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