Go中http超時(shí)問題的排查及解決方法

背景

最新有同事反饋，服務(wù)間有調(diào)用超時(shí)的現(xiàn)象，在業(yè)務(wù)高峰期發(fā)生的概率和次數(shù)比較高。從日志中調(diào)用關(guān)系來看，有2個(gè)調(diào)用鏈經(jīng)常發(fā)生超時(shí)問題。

問題1： A服務(wù)使用 http1.1 發(fā)送請求到 B 服務(wù)超時(shí)。

問題2: A服務(wù)使用一個(gè)輕量級http-sdk(內(nèi)部http2.0) 發(fā)送請求到 C 服務(wù)超時(shí)。

Golang給出的報(bào)錯(cuò)信息時(shí)：

Post http://host/v1/xxxx: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)

通知日志追蹤ID來排查，發(fā)現(xiàn)有的請求還沒到服務(wù)方就已經(jīng)超時(shí)。

有些已經(jīng)到服務(wù)方了，但也超時(shí)。

這里先排查的是問題2，下面是過程。

排查

推測

調(diào)用方設(shè)置的http請求超時(shí)時(shí)間是1s。

請求已經(jīng)到服務(wù)端了還超時(shí)的原因，可能是：

1. 服務(wù)方響應(yīng)慢。 通過日志排查確實(shí)有部分存在。
2. 客戶端調(diào)用花了990ms，到服務(wù)端只剩10ms，這個(gè)肯定會(huì)超時(shí)。

請求沒到服務(wù)端超時(shí)的原因，可能是：

1. golang CPU調(diào)度不過來。通過cpu監(jiān)控排除這個(gè)可能性
2. golang 網(wǎng)絡(luò)庫原因。重點(diǎn)排查

排查方法：

本地寫個(gè)測試程序，1000并發(fā)調(diào)用測試環(huán)境的C服務(wù):

n := 1000
var waitGroutp = sync.WaitGroup{}
waitGroutp.Add(n)
for i := 0; i  n; i++ {
 go func(x int) {
  httpSDK.Request()
 }
}
waitGroutp.Wait()

報(bào)錯(cuò)：

too many open files // 這個(gè)錯(cuò)誤是筆者本機(jī)ulimit太小的原因，可忽略 net/http: request canceled (Client.Timeout exceeded while awaiting headers)

并發(fā)數(shù)量調(diào)整到500繼續(xù)測試，還是報(bào)同樣的錯(cuò)誤。

連接超時(shí)

本地如果能重現(xiàn)的問題，一般來說比較好查些。

開始跟golang的源碼，下面是創(chuàng)建httpClient的代碼，這個(gè)httpClient是全局復(fù)用的。

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 {
 }
}

繼續(xù)進(jìn) send 方法，實(shí)際發(fā)送請求是通過 RoundTrip 函數(shù)。

func send(ireq *Request, rt RoundTripper, deadline time.Time) (resp *Response, didTimeout func() bool, err error) {
 rt.RoundTrip(req) 
}

send 函數(shù)接收的 rt 參數(shù)是個(gè) inteface，所以要從 http.Transport 進(jìn)到 RoundTrip 函數(shù)。

其中log.Println("getConn time", time.Now().Sub(start), x) 是筆者添加的日志，為了驗(yàn)證創(chuàng)建連接耗時(shí)。

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
 }
 }
}

結(jié)論：加了日志跑下來，確實(shí)有大量的getConn time超時(shí)。

疑問

這里有2個(gè)疑問：

1. 為什么Http2沒復(fù)用連接，反而會(huì)創(chuàng)建大量連接？
2. 創(chuàng)建連接為什么會(huì)越來越慢？

繼續(xù)跟 getConn 源碼, getConn第一步會(huì)先獲取空閑連接，因?yàn)檫@里用的是http2，可以不用管它。

追加耗時(shí)日志，確認(rèn)是dialConn耗時(shí)的。

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)
}

繼續(xù)跟dialConn函數(shù)，里面有2個(gè)比較耗時(shí)的地方：

連接建立，三次握手。

tls握手的耗時(shí)，見下面http2章節(jié)的dialConn源碼。

分別在dialConn函數(shù)中 t.dial 和 addTLS 的位置追加日志。

可以看到，三次握手的連接還是比較穩(wěn)定的，后面連接的在tls握手耗時(shí)上面，耗費(fèi)將近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

結(jié)論：第二個(gè)疑問的答案就是tls握手耗時(shí)

http2

為什么Http2沒復(fù)用連接，反而會(huì)創(chuàng)建大量連接？

前面創(chuàng)建http.Client 時(shí)，是通過http2.ConfigureTransport(transport) 方法，其內(nèi)部調(diào)用了configureTransport：

func configureTransport(t1 *http.Transport) (*Transport, error) {
 // 聲明一個(gè)連接池
 // noDialClientConnPool 這里很關(guān)鍵，指明連接不需要dial出來的，而是由http1連接升級而來的 
 connPool := new(clientConnPool)
 t2 := Transport{
 ConnPool: noDialClientConnPool{connPool},
 t1: t1,
 }
 connPool.t = t2
// 把http2的RoundTripp的方法注冊到，http1上transport的altProto變量上。
// 當(dāng)請求使用http1的roundTrip方法時(shí)，檢查altProto是否有注冊的http2，有的話，則使用
// 前面代碼的useRegisteredProtocol就是檢測方法
 if err := registerHTTPSProtocol(t1, noDialH2RoundTripper{t2}); err != nil  {
 return nil, err
 }
 // http1.1 升級到http2的后的回調(diào)函數(shù)，會(huì)把連接通過 addConnIfNeeded 函數(shù)把連接添加到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 中使用。調(diào)用upgradeFn函數(shù)，返回http2的RoundTripper，賦值給alt。

alt會(huì)在http.Transport 中 RoundTripper 內(nèi)部檢查調(diào)用。

func (t *Transport) dialConn(ctx context.Context, cm connectMethod) (*persistConn, error) {
 pconn := persistConn{
 t:  t,
 }
 if cm.scheme() == "https"  t.DialTLS != nil {
 // 沒有自定義DialTLS方法，不會(huì)走到這一步
 } else {
 conn, err := t.dial(ctx, "tcp", cm.addr())
 if err != nil {
  return nil, wrapErr(err)
 }
 pconn.conn = conn
 if cm.scheme() == "https" {
  // addTLS 里進(jìn)行 tls 握手，也是建立新連接最耗時(shí)的地方。
  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 調(diào)用注冊的升級函數(shù)
  return persistConn{t: t, cacheKey: pconn.cacheKey, alt: next(cm.targetAddr, pconn.conn.(*tls.Conn))}, nil
 }
 }
 return pconn, nil
}

結(jié)論：

當(dāng)沒有連接時(shí)，如果此時(shí)來一大波請求，會(huì)創(chuàng)建n多http1.1的連接，進(jìn)行升級和握手，而tls握手隨著連接增加而變的非常慢。

解決超時(shí)

上面的結(jié)論并不能完整解釋，復(fù)用連接的問題。因?yàn)榉?wù)正常運(yùn)行的時(shí)候，一直都有請求的，連接是不會(huì)斷開的，所以除了第一次連接或網(wǎng)絡(luò)原因斷開，正常情況下都應(yīng)該復(fù)用http2連接。

通過下面測試，可以復(fù)現(xiàn)有http2的連接時(shí)，還是會(huì)創(chuàng)建N多新連接：

sdk.Request() // 先請求一次，建立好連接，測試是否一直復(fù)用連接。
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升級導(dǎo)致，這次直接改成使用 http2.Transport

httpClient.Transport = http2.Transport{
  TLSClientConfig: tlsConfig,
}

改了后，測試發(fā)現(xiàn)沒有報(bào)錯(cuò)了。

為了驗(yàn)證升級模式和直接http2模式的區(qū)別。 這里先回到升級模式中的 addConnIfNeeded 函數(shù)中，其會(huì)調(diào)用addConnCall 的 run 函數(shù)：

func (c *addConnCall) run(t *Transport, key string, tc *tls.Conn) {
 cc, err := t.NewClientConn(tc)
}

run參數(shù)中傳入的是http2的transport。

整個(gè)解釋是http1.1創(chuàng)建連接后，會(huì)把傳輸層連接，通過addConnIfNeeded->run->Transport.NewClientConn構(gòu)成一個(gè)http2連接。 因?yàn)閔ttp2和http1.1本質(zhì)都是應(yīng)用層協(xié)議，傳輸層的連接都是一樣的。

然后在newClientConn連接中加日志。

func (t *Transport) newClientConn(c net.Conn, singleUse bool) (*ClientConn, error) {
 // log.Println("http2.newClientConn")
}

結(jié)論：

升級模式下，會(huì)打印很多http2.newClientConn，根據(jù)前面的排查這是講的通的。而單純http2模式下，也會(huì)創(chuàng)建新連接，雖然很少。

并發(fā)連接數(shù)

那http2模式下什么情況下會(huì)創(chuàng)建新連接呢？

這里看什么情況下http2會(huì)調(diào)用 newClientConn?；氐絚lientConnPool中，dialOnMiss在http2模式下為true，getStartDialLocked 里會(huì)調(diào)用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，也會(huì)創(chuàng)建新連接?？纯催@個(gè)變量是這么得來的：

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
}

為了查問題，這里加了詳細(xì)日志。測試下來，發(fā)現(xiàn)是maxConcurrentStreams 超了，canTakeNewRequest才為false。

在http2中newClientConn的初始化配置中, maxConcurrentStreams 默認(rèn)為1000：

maxConcurrentStreams: 1000, // "infinite", per spec. 1000 seems good enough.

但實(shí)際測下來，發(fā)現(xiàn)500并發(fā)也會(huì)創(chuàng)建新連接。繼續(xù)追查有設(shè)置這個(gè)變量的地方：

func (rl *clientConnReadLoop) processSettings(f *SettingsFrame) error {
 case SettingMaxConcurrentStreams:
  cc.maxConcurrentStreams = s.Val
  //log.Println("maxConcurrentStreams", s.Val)
}

運(yùn)行測試，發(fā)現(xiàn)是服務(wù)傳過來的配置，值是250。

結(jié)論： 服務(wù)端限制了單連接并發(fā)連接數(shù)，超了后就會(huì)創(chuàng)建新連接。

服務(wù)端限制

在服務(wù)端框架中，找到ListenAndServeTLS函數(shù)，跟下去->ServeTLS->Serve->setupHTTP2_Serve-

>onceSetNextProtoDefaults_Serve->onceSetNextProtoDefaults->http2ConfigureServer。

查到new(http2Server)的聲明，因?yàn)閣eb框架即支持http1.1 也支持http2，所以沒有指定任何http2的相關(guān)配置，都使用的是默認(rèn)的。

// 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標(biāo)準(zhǔn)推薦至少為100，golang中使用默認(rèn)變量 http2defaultMaxStreams， 它的值為250。

真相

上面的步驟，更多的是為了記錄排查過程和源碼中的關(guān)鍵點(diǎn)，方便以后類似問題有個(gè)參考。

簡化來說：

1. 調(diào)用方和服務(wù)方使用http1.1升級到http2的模式進(jìn)行通訊
2. 服務(wù)方http2Server限制單連接并發(fā)數(shù)是250
3. 當(dāng)并發(fā)超過250，比如1000時(shí)，調(diào)用方就會(huì)并發(fā)創(chuàng)建750個(gè)連接。這些連接的tls握手時(shí)間會(huì)越來越長。而調(diào)用超時(shí)只有1s，所以導(dǎo)致大量超時(shí)。
4. 這些連接有些沒到服務(wù)方就超時(shí)，有些到了但服務(wù)方還沒來得及處理，調(diào)用方就取消連接了，也是超時(shí)。
5. 并發(fā)量高的情況下，如果有網(wǎng)絡(luò)斷開，也會(huì)導(dǎo)致這種情況發(fā)送。

重試

A服務(wù)使用的輕量級http-sdk有一個(gè)重試機(jī)制，當(dāng)檢測到是一個(gè)臨時(shí)錯(cuò)誤時(shí)，會(huì)重試2次。

Temporary() bool // Is the error temporary? 而這個(gè)超時(shí)錯(cuò)誤，就屬于臨時(shí)錯(cuò)誤，從而放大了這種情況發(fā)生。

解決辦法

不是升級模式的http2即可。

httpClient.Transport = http2.Transport{
  TLSClientConfig: tlsConfig,
}

為什么http2不會(huì)大量創(chuàng)建連接呢？

這是因?yàn)閔ttp2創(chuàng)建新連接時(shí)會(huì)加鎖，后面的請求解鎖后，發(fā)現(xiàn)有連接沒超過并發(fā)數(shù)時(shí)，直接復(fù)用連接即可。所以沒有這種情況，這個(gè)鎖在 clientConnPool.getStartDialLocked 源碼中。

問題1

問題1： A服務(wù)使用 http1.1 發(fā)送請求到 B 服務(wù)超時(shí)。

問題1和問題2的原因一樣，就是高并發(fā)來的情況下，會(huì)創(chuàng)建大量連接，連接的創(chuàng)建會(huì)越來越慢，從而超時(shí)。

這種情況沒有很好的辦法解決，推薦使用http2。

如果不能使用http2，調(diào)大MaxIdleConnsPerHost參數(shù)，可以緩解這種情況。默認(rèn)http1.1給每個(gè)host只保留2個(gè)空閑連接，來個(gè)1000并發(fā)，就要?jiǎng)?chuàng)建998新連接。

該調(diào)整多少，可以視系統(tǒng)情況調(diào)整，比如50，100。

總結(jié)

以上所述是小編給大家介紹的Go中http超時(shí)問題的排查及解決方法,希望對大家有所幫助，如果大家有任何疑問請給我留言，小編會(huì)及時(shí)回復(fù)大家的。在此也非常感謝大家對腳本之家網(wǎng)站的支持！如果你覺得本文對你有幫助，歡迎轉(zhuǎn)載，煩請注明出處，謝謝！