i-o timeout ，希望你不要踩到這個 net-http 包的坑

問題

我們來看一段日常代碼。

package main

import (
    "bytes"
    "encoding/json"
    "fmt"
    "io/ioutil"
    "net"
    "net/http"
    "time"
)

var tr *http.Transport

func init() {
    tr = &http.Transport{
        MaxIdleConns: 100,
        Dial: func(netw, addr string) (net.Conn, error) {
            conn, err := net.DialTimeout(netw, addr, time.Second*2) //設置建立連接超時
            if err != nil {
                return nil, err
            }
            err = conn.SetDeadline(time.Now().Add(time.Second * 3)) //設置發送接受數據超時
            if err != nil {
                return nil, err
            }
            return conn, nil
        },
    }
}

func main() {
    for {
        _, err := Get("http://www.baidu.com/")
        if err != nil {
            fmt.Println(err)
            break
        }
    }
}


func Get(url string) ([]byte, error) {
    m := make(map[string]interface{})
    data, err := json.Marshal(m)
    if err != nil {
        return nil, err
    }
    body := bytes.NewReader(data)
    req, _ := http.NewRequest("Get", url, body)
    req.Header.Add("content-type", "application/json")

    client := &http.Client{
        Transport: tr,
    }
    res, err := client.Do(req)
    if res != nil {
        defer res.Body.Close()
    }
    if err != nil {
        return nil, err
    }
    resBody, err := ioutil.ReadAll(res.Body)
    if err != nil {
        return nil, err
    }
    return resBody, nil
}

做的事情，比較簡單，就是循環去請求 http://www.baidu.com/ , 然後等待響應。

看上去貌似沒啥問題吧。

代碼跑起來，也確實能正常收發消息。

但是這段代碼跑一段時間，就會出現 i/o timeout 的報錯。

這其實是最近排查了的一個問題，發現這個坑可能比較容易踩上，我這邊對代碼做了簡化。

實際生產中發生的現象是，golang服務在發起http調用時，雖然http.Transport設置了3s超時，會偶發出現i/o timeout的報錯。

但是查看下游服務的時候，發現下游服務其實 100ms 就已經返回了。

排查

五層網絡協議對應的消息體變化分析

就很奇怪了，明明服務端顯示處理耗時才100ms，且客戶端超時設的是3s, 怎麼就出現超時報錯 i/o timeout 呢？

這裏推測有兩個可能。

因爲服務端打印的日誌其實只是服務端應用層打印的日誌。但客戶端應用層發出數據後，中間還經過客戶端的傳輸層，網絡層，數據鏈路層和物理層，再經過服務端的物理層，數據鏈路層，網絡層，傳輸層到服務端的應用層。服務端應用層處耗時 100ms，再原路返回。那剩下的3s-100ms可能是耗在了整個流程裏的各個層上。比如網絡不好的情況下，傳輸層 TCP 使勁丟包重傳之類的原因。
網絡沒問題，客戶端到服務端鏈路整個收發流程大概耗時就是100ms左右。客戶端處理邏輯問題導致超時。

一般遇到問題，大部分情況下都不會是底層網絡的問題，大膽懷疑是自己的問題就對了，不死心就抓個包看下。

抓包結果

分析下，從剛開始三次握手（畫了紅框的地方）。

到最後出現超時報錯 i/o timeout （畫了藍框的地方）。

從time那一列從7到10，確實間隔3s。而且看右下角的藍框，是51169端口發到80端口的一次Reset連接。

80端口是服務端的端口。換句話說就是客戶端3s超時主動斷開鏈接的。

但是再仔細看下第一行三次握手到最後客戶端超時主動斷開連接的中間，其實有非常多次 HTTP 請求。

回去看代碼設置超時的方式。

tr = &http.Transport{
    MaxIdleConns: 100,
    Dial: func(netw, addr string) (net.Conn, error) {
        conn, err := net.DialTimeout(netw, addr, time.Second*2) //設置建立連接超時
        if err != nil {
            return nil, err
        }
        err = conn.SetDeadline(time.Now().Add(time.Second * 3)) //設置發送接受數據超時
        if err != nil {
            return nil, err
        }
        return conn, nil
    },
}

也就是說，這裏的3s超時，其實是在建立連接之後開始算的，而不是單次調用開始算的超時。

看註釋裏寫的是

SetDeadline sets the read and write deadlines associated with the connection.

超時原因

大家知道HTTP是應用層協議，傳輸層用的是TCP協議。

HTTP 協議從1.0以前，默認用的是短連接，每次發起請求都會建立 TCP 連接。收發數據。然後斷開連接。

TCP 連接每次都是三次握手。每次斷開都要四次揮手。

其實沒必要每次都建立新連接，建立的連接不斷開就好了，每次發送數據都複用就好了。

於是乎，HTTP 協議從1.1之後就默認使用長連接。具體相關信息可以看之前的這篇文章。

那麼golang標準庫裏也兼容這種實現。

通過建立一個連接池，針對每個域名建立一個 TCP 長連接，比如http://baidu.com和http://golang.com 就是兩個不同的域名。

第一次訪問http://baidu.com 域名的時候會建立一個連接，用完之後放到空閒連接池裏，下次再要訪問http://baidu.com 的時候會重新從連接池裏把這個連接撈出來複用。

複用長連接

插個題外話：這也解釋了之前這篇文章裏最後的疑問，爲什麼要強調是同一個域名：一個域名會建立一個連接，一個連接對應一個讀 goroutine 和一個寫 goroutine。正因爲是同一個域名，所以最後纔會泄漏3個 goroutine，如果不同域名的話，那就會泄漏 1+2*N 個協程，N就是域名數。

假設第一次請求要100ms，每次請求完http://baidu.com 後都放入連接池中，下次繼續複用，重複29次，耗時2900ms。

第30次請求的時候，連接從建立開始到服務返回前就已經用了3000ms，剛好到設置的 3s 超時閾值，那麼此時客戶端就會報超時 i/o timeout 。

雖然這時候服務端其實才花了100ms，但耐不住前面29次加起來的耗時已經很長。

也就是說只要通過 http.Transport 設置了 err = conn.SetDeadline(time.Now().Add(time.Second * 3))，並且你用了長連接，哪怕服務端處理再快，客戶端設置的超時再長，總有一刻，你的程序會報超時錯誤。

正確姿勢

原本預期是給每次調用設置一個超時，而不是給整個連接設置超時。

另外，上面出現問題的原因是給長連接設置了超時，且長連接會複用。

基於這兩點，改一下代碼。

package main

import (
    "bytes"
    "encoding/json"
    "fmt"
    "io/ioutil"
    "net/http"
    "time"
)

var tr *http.Transport

func init() {
    tr = &http.Transport{
        MaxIdleConns: 100,
        // 下面的代碼被幹掉了
        //Dial: func(netw, addr string) (net.Conn, error) {
        //  conn, err := net.DialTimeout(netw, addr, time.Second*2) //設置建立連接超時
        //  if err != nil {
        //      return nil, err
        //  }
        //  err = conn.SetDeadline(time.Now().Add(time.Second * 3)) //設置發送接受數據超時
        //  if err != nil {
        //      return nil, err
        //  }
        //  return conn, nil
        //},
    }
}


func Get(url string) ([]byte, error) {
    m := make(map[string]interface{})
    data, err := json.Marshal(m)
    if err != nil {
        return nil, err
    }
    body := bytes.NewReader(data)
    req, _ := http.NewRequest("Get", url, body)
    req.Header.Add("content-type", "application/json")

    client := &http.Client{
        Transport: tr,
        Timeout: 3*time.Second,  // 超時加在這裏，是每次調用的超時
    }
    res, err := client.Do(req) 
    if res != nil {
        defer res.Body.Close()
    }
    if err != nil {
        return nil, err
    }
    resBody, err := ioutil.ReadAll(res.Body)
    if err != nil {
        return nil, err
    }
    return resBody, nil
}

func main() {
    for {
        _, err := Get("http://www.baidu.com/")
        if err != nil {
            fmt.Println(err)
            break
        }
    }
}

看註釋會發現，改動的點有兩個

http.Transport裏的建立連接時的一些超時設置幹掉了。
在發起 http 請求的時候會場景http.Client，此時加入超時設置，這裏的超時就可以理解爲單次請求的超時了。同樣可以看下注釋

Timeout specifies a time limit for requests made by this Client.

到這裏，代碼就改好了，實際生產中問題也就解決了。

實例代碼裏，如果拿去跑的話，其實還會下面的錯

1Get http://www.baidu.com/: EOF

這個是因爲調用得太猛了，http://www.baidu.com 那邊主動斷開的連接，可以理解爲一個限流措施，目的是爲了保護服務器，畢竟每個人都像這麼搞，服務器是會炸的。。。

解決方案很簡單，每次 HTTP 調用中間加個sleep間隔時間就好。

到這裏，其實問題已經解決了，下面會在源碼層面分析出現問題的原因。對讀源碼不感興趣的朋友們可以不用接着往下看，直接拉到文章底部右下角，做點正能量的事情（點兩下）支持一下。（瘋狂暗示，拜託拜託，這對我真的很重要！）

源碼分析

用的 go 版本是 1.12.7。

從發起一個網絡請求開始跟。

res, err := client.Do(req)
func (c *Client) Do(req *Request) (*Response, error) {
    return c.do(req)
}

func (c *Client) do(req *Request) {
    // ...
    if resp, didTimeout, err = c.send(req, deadline); err != nil {
    // ...
  }
    // ...  
}  
func send(ireq *Request, rt RoundTripper, deadline time.Time) {
    // ...    
    resp, err = rt.RoundTrip(req)
     // ...  
} 

// 從這裏進入 RoundTrip 邏輯
/src/net/http/roundtrip.go: 16
func (t *Transport) RoundTrip(req *Request) (*Response, error) {
    return t.roundTrip(req)
}

func (t *Transport) roundTrip(req *Request) (*Response, error) {
    // 嘗試去獲取一個空閒連接，用於發起 http 連接
  pconn, err := t.getConn(treq, cm)
  // ...
}

// 重點關注這個函數，返回是一個長連接
func (t *Transport) getConn(treq *transportRequest, cm connectMethod) (*persistConn, error) {
  // 省略了大量邏輯，只關注下面兩點
    // 有空閒連接就返回
    pc := <-t.getIdleConnCh(cm)

  // 沒有創建連接
  pc, err := t.dialConn(ctx, cm)

}

這裏上面很多代碼，其實只是爲了展示這部分代碼是怎麼跟蹤下來的，方便大家去看源碼的時候去跟一下。

最後一個上面的代碼裏有個 getConn 方法。在發起網絡請求的時候，會先取一個網絡連接，取連接有兩個來源。

如果有空閒連接，就拿空閒連接

/src/net/http/tansport.go:810
func (t *Transport) getIdleConnCh(cm connectMethod) chan *persistConn {
 // 返回放空閒連接的chan
 ch, ok := t.idleConnCh[key]
   // ...
 return ch
}

沒有空閒連接，就創建長連接。

/src/net/http/tansport.go:1357
func (t *Transport) dialConn() {
  //...
  conn, err := t.dial(ctx, "tcp", cm.addr())
  // ...
  go pconn.readLoop()
  go pconn.writeLoop()
  // ...
}

當第一次發起一個 http 請求時，這時候肯定沒有空閒連接，會建立一個新連接。同時會創建一個讀 goroutine 和一個寫 goroutine。

讀寫協程

注意上面代碼裏的t.dial(ctx, "tcp", cm.addr())，如果像文章開頭那樣設置了 http.Transport的

Dial: func(netw, addr string) (net.Conn, error) {
   conn, err := net.DialTimeout(netw, addr, time.Second*2) //設置建立連接超時
   if err != nil {
      return nil, err
   }
   err = conn.SetDeadline(time.Now().Add(time.Second * 3)) //設置發送接受數據超時
   if err != nil {
      return nil, err
   }
   return conn, nil
},

那麼這裏就會在下面的dial裏被執行到

func (t *Transport) dial(ctx context.Context, network, addr string) (net.Conn, error) {
   // ...
  c, err := t.Dial(network, addr)
  // ...
}

這裏面調用的設置超時，會執行到

/src/net/net.go
func (c *conn) SetDeadline(t time.Time) error {
    //...
    c.fd.SetDeadline(t)
    //...
}

//...

func setDeadlineImpl(fd *FD, t time.Time, mode int) error {
    // ...
    runtime_pollSetDeadline(fd.pd.runtimeCtx, d, mode)
    return nil
}


//go:linkname poll_runtime_pollSetDeadline internal/poll.runtime_pollSetDeadline
func poll_runtime_pollSetDeadline(pd *pollDesc, d int64, mode int) {
    // ...
  // 設置一個定時器事件
  rtf = netpollDeadline
    // 並將事件註冊到定時器裏
  modtimer(&pd.rt, pd.rd, 0, rtf, pd, pd.rseq)
}

上面的源碼，簡單來說就是，當第一次調用請求的，會建立個連接，這時候還會註冊一個定時器事件，假設時間設了3s，那麼這個事件會在3s後發生，然後執行註冊事件的邏輯。而這個註冊事件就是netpollDeadline。 注意這個netpollDeadline，待會會提到。

讀寫協程定時器事件

設置了超時事件，且超時事件是 3s 後之後，發生。再次期間正常收發數據。一切如常。

直到3s過後，這時候看讀goroutine，會等待網絡數據返回。

/src/net/http/tansport.go:1642
func (pc *persistConn) readLoop() {
    //...
    for alive {
        _, err := pc.br.Peek(1)  // 阻塞讀取服務端返回的數據
    //...
}

然後就是一直跟代碼。

src/bufio/bufio.go: 129
func (b *Reader) Peek(n int) ([]byte, error) {
   // ...
   b.fill() 
   // ...   
}

func (b *Reader) fill() {
    // ...
    n, err := b.rd.Read(b.buf[b.w:])
    // ...
}

/src/net/http/transport.go: 1517
func (pc *persistConn) Read(p []byte) (n int, err error) {
    // ...
    n, err = pc.conn.Read(p)
    // ...
}

// /src/net/net.go: 173
func (c *conn) Read(b []byte) (int, error) {
    // ...
    n, err := c.fd.Read(b)
    // ...
}

func (fd *netFD) Read(p []byte) (n int, err error) {
    n, err = fd.pfd.Read(p)
    // ...
}

/src/internal/poll/fd_unix.go: 
func (fd *FD) Read(p []byte) (int, error) {
    //...
  if err = fd.pd.waitRead(fd.isFile); err == nil {
    continue
  }
    // ...
}

func (pd *pollDesc) waitRead(isFile bool) error {
    return pd.wait('r', isFile)
}

func (pd *pollDesc) wait(mode int, isFile bool) error {
    // ...
  res := runtime_pollWait(pd.runtimeCtx, mode)
    return convertErr(res, isFile)
}

直到跟到 runtime_pollWait，這個可以簡單認爲是等待服務端數據返回。

//go:linkname poll_runtime_pollWait internal/poll.runtime_pollWait
func poll_runtime_pollWait(pd *pollDesc, mode int) int {

    // 1.如果網絡正常返回數據就跳出
  for !netpollblock(pd, int32(mode), false) {
    // 2.如果有出錯情況也跳出
        err = netpollcheckerr(pd, int32(mode))
        if err != 0 {
            return err
        }
    }
    return 0
}

整條鏈路跟下來，就是會一直等待數據，等待的結果只有兩個

有可以讀的數據
出現報錯

這裏面的報錯，又有那麼兩種

連接關閉
超時

func netpollcheckerr(pd *pollDesc, mode int32) int {
    if pd.closing {
        return 1 // errClosing
    }
    if (mode == 'r' && pd.rd < 0) || (mode == 'w' && pd.wd < 0) {
        return 2 // errTimeout
    }
    return 0
}

其中提到的超時，就是指這裏面返回的數字2，會通過下面的函數，轉化爲 ErrTimeout，而 ErrTimeout.Error() 其實就是 i/o timeout。

func convertErr(res int, isFile bool) error {
    switch res {
    case 0:
        return nil
    case 1:
        return errClosing(isFile)
    case 2:
        return ErrTimeout // ErrTimeout.Error() 就是 "i/o timeout"
    }
    println("unreachable: ", res)
    panic("unreachable")
}

那麼問題來了。上面返回的超時錯誤，也就是返回 2 的時候的條件是怎麼滿足的？

if (mode == 'r' && pd.rd < 0) || (mode == 'w' && pd.wd < 0) {
    return 2 // errTimeout
}

還記得剛剛提到的 netpollDeadline嗎？

這裏面放了定時器3s到點時執行的邏輯。

func timerproc(tb *timersBucket) {
    // 計時器到設定時間點了，觸發之前註冊函數
    f(arg, seq) // 之前註冊的是 netpollDeadline
}

func netpollDeadline(arg interface{}, seq uintptr) {
    netpolldeadlineimpl(arg.(*pollDesc), seq, true, true)
}

/src/runtime/netpoll.go: 428
func netpolldeadlineimpl(pd *pollDesc, seq uintptr, read, write bool) {
    //...
    if read {
        pd.rd = -1
        rg = netpollunblock(pd, 'r', false)
    }
    //...
}

這裏會設置pd.rd=-1，是指 poller descriptor.read deadline ，含義網絡輪詢器文件描述符的讀超時時間，我們知道在 linux 裏萬物皆文件，這裏的文件其實是指這次網絡通訊中使用到的 socket。

這時候再回去看發生超時的條件就是if (mode == 'r' && pd.rd < 0)。

至此。我們的代碼裏就收到了 io timeout 的報錯。

總結

不要在 http.Transport中設置超時，那是連接的超時，不是請求的超時。否則可能會出現莫名 io timeout報錯。
請求的超時在創建client裏設置。

本文由 Readfog 進行 AMP 轉碼，版權歸原作者所有。
來源：https://mp.weixin.qq.com/s/BiPbzpyxO2DJ4x-PUDrRjg

問題

排查

超時原因

正確姿勢

源碼分析

總結

猜你喜歡