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

xiaobai9發表於2021-05-29
HTTP

文章持續更新，可以微信搜一搜「golang小白成長記」第一時間閱讀，回覆【教程】獲golang免費視訊教程。本文已經收錄在GitHub github.com/xiaobaiTech/golangFamil... , 有大廠面試完整考點和成長路線，歡迎Star。


問題

我們來看一段日常程式碼。

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.

到這裡，程式碼就改好了，實際生產中問題也就解決了。

例項程式碼裡，如果拿去跑的話，其實還會下面的錯

Get 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裡設定。

如果文章對你有幫助，看下文章底部右下角，做點正能量的事情（點兩下）支援一下。（瘋狂暗示，拜託拜託，這對我真的很重要！）

我是小白，我們下期見。

文章推薦：

別說了，一起在知識的海洋裡嗆水吧

關注公眾號:【golang小白成長記】

本作品採用《CC 協議》，轉載必須註明作者和本文連結

相關文章