中文字幕av专区_日韩电影在线播放_精品国产精品久久一区免费式_av在线免费观看网站

溫馨提示×

溫馨提示×

您好,登錄后才能下訂單哦!

密碼登錄×
登錄注冊×
其他方式登錄
點擊 登錄注冊 即表示同意《億速云用戶服務條款》

Go中http超時問題的排查及解決方法

發布時間:2020-10-05 02:13:05 來源:腳本之家 閱讀:1026 作者:蘑菇先生 欄目:編程語言

背景

最新有同事反饋,服務間有調用超時的現象,在業務高峰期發生的概率和次數比較高。從日志中調用關系來看,有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個比較耗時的地方:

連接建立,三次握手。

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{
  "h3": upgradeFn,
 }
 } else {
 m["h3"] = 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. 這些連接有些沒到服務方就超時,有些到了但服務方還沒來得及處理,調用方就取消連接了,也是超時。
  5. 并發量高的情況下,如果有網絡斷開,也會導致這種情況發送。

重試

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。

總結

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

向AI問一下細節

免責聲明:本站發布的內容(圖片、視頻和文字)以原創、轉載和分享為主,文章觀點不代表本網站立場,如果涉及侵權請聯系站長郵箱:is@yisu.com進行舉報,并提供相關證據,一經查實,將立刻刪除涉嫌侵權內容。

AI

沈阳市| 莱州市| 新密市| 东兰县| 琼海市| 霍山县| 淳化县| 巴中市| 泰和县| 遵化市| 焦作市| 宜兰市| 北宁市| 武穴市| 夏河县| 克东县| 临邑县| 灵宝市| 石渠县| 固原市| 清徐县| 和顺县| 芷江| 达孜县| 左贡县| 册亨县| 崇信县| 石屏县| 宾川县| 嘉兴市| 张家口市| 曲周县| 北碚区| 锡林浩特市| 堆龙德庆县| 张掖市| 扬州市| 黑水县| 汉沽区| 辉县市| 扎囊县|