背景

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

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

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

Golang給出的報錯信息時：

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)超時。

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

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

排查

推測

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

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

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

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

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

排查方法：

本地寫個測試程序，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()

報錯：

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

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

連接超時

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

開始跟golang的源碼，下面是創(chuàng)建httpClient的代碼，這個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ù)是個 inteface，所以要從 http.Transport 進(jìn)到 RoundTrip 函數(shù)。

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

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超時。

疑問

這里有2個疑問：

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

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

追加耗時日志，確認(rèn)是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)
}

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

連接建立，三次握手。

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

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

可以看到，三次握手的連接還是比較穩(wěn)定的，后面連接的在tls握手耗時上面，耗費(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é)論：第二個疑問的答案就是tls握手耗時

http2

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

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

func configureTransport(t1 *http.Transport) (*Transport, error) {
 // 聲明一個連接池
 // 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方法時，檢查altProto是否有注冊的http2，有的話，則使用
// 前面代碼的useRegisteredProtocol就是檢測方法
 if err := registerHTTPSProtocol(t1, noDialH2RoundTripper{t2}); err != nil  {
 return nil, err
 }
 // http1.1 升級到http2的后的回調(diào)函數(shù)，會把連接通過 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會在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方法，不會走到這一步
 } 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 握手，也是建立新連接最耗時的地方。
  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)沒有連接時，如果此時來一大波請求，會創(chuàng)建n多http1.1的連接，進(jìn)行升級和握手，而tls握手隨著連接增加而變的非常慢。

解決超時

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

通過下面測試，可以復(fù)現(xiàn)有http2的連接時，還是會創(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)沒有報錯了。

為了驗(yàn)證升級模式和直接http2模式的區(qū)別。 這里先回到升級模式中的 addConnIfNeeded 函數(shù)中，其會調(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。

整個解釋是http1.1創(chuàng)建連接后，會把傳輸層連接，通過addConnIfNeeded->run->Transport.NewClientConn構(gòu)成一個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é)論：

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

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

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

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

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ā)也會創(chuàng)建新連接。繼續(xù)追查有設(shè)置這個變量的地方：

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ù)，超了后就會創(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)，方便以后類似問題有個參考。

簡化來說：

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

重試

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

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

解決辦法

不是升級模式的http2即可。

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

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

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

問題1

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

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

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

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

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

總結(jié)

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