溫馨提示×
您好，登錄后才能下訂單哦！
點擊 登錄注冊 即表示同意《億速云用戶服務條款》
您好，登錄后才能下訂單哦！
最新有同事反饋，服務間有調用超時的現象，在業務高峰期發生的概率和次數比較高。從日志中調用關系來看，有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。
請求已經到服務端了還超時的原因，可能是：
請求沒到服務端超時的原因，可能是：
排查方法：
本地寫個測試程序，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個疑問：
繼續跟 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沒復用連接，反而會創建大量連接？
前面創建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。
上面的步驟，更多的是為了記錄排查過程和源碼中的關鍵點，方便以后類似問題有個參考。
簡化來說：
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超時問題的排查及解決方法,希望對大家有所幫助，如果大家有任何疑問請給我留言，小編會及時回復大家的。在此也非常感謝大家對億速云網站的支持！如果你覺得本文對你有幫助，歡迎轉載，煩請注明出處，謝謝！
免責聲明：本站發布的內容（圖片、視頻和文字）以原創、轉載和分享為主，文章觀點不代表本網站立場，如果涉及侵權請聯系站長郵箱：is@yisu.com進行舉報，并提供相關證據，一經查實，將立刻刪除涉嫌侵權內容。
