i/o timeout ，希望你不要踩到這個net/http包的坑-Golang-PHP中文網

問題" >問題

排查" >排查

逾時原因" >逾時原因

正确姿势" >正确姿势

源码分析" >源码分析

總結" >總結

首頁

後端開發

Golang

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

Go语言进阶学习

Jul 25, 2023 pm 03:56 PM

timeout net/http

問題

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

 1package main
 2
 3import (
 4    "bytes"
 5    "encoding/json"
 6    "fmt"
 7    "io/ioutil"
 8    "net"
 9    "net/http"
10    "time"
11)
12
13var tr *http.Transport
14
15func init() {
16    tr = &http.Transport{
17        MaxIdleConns: 100,
18        Dial: func(netw, addr string) (net.Conn, error) {
19            conn, err := net.DialTimeout(netw, addr, time.Second*2) //设置建立连接超时
20            if err != nil {
21                return nil, err
22            }
23            err = conn.SetDeadline(time.Now().Add(time.Second * 3)) //设置发送接受数据超时
24            if err != nil {
25                return nil, err
26            }
27            return conn, nil
28        },
29    }
30}
31
32func main() {
33    for {
34        _, err := Get("http://www.baidu.com/")
35        if err != nil {
36            fmt.Println(err)
37            break
38        }
39    }
40}
41
42
43func Get(url string) ([]byte, error) {
44    m := make(map[string]interface{})
45    data, err := json.Marshal(m)
46    if err != nil {
47        return nil, err
48    }
49    body := bytes.NewReader(data)
50    req, _ := http.NewRequest("Get", url, body)
51    req.Header.Add("content-type", "application/json")
52
53    client := &http.Client{
54        Transport: tr,
55    }
56    res, err := client.Do(req)
57    if res != nil {
58        defer res.Body.Close()
59    }
60    if err != nil {
61        return nil, err
62    }
63    resBody, err := ioutil.ReadAll(res.Body)
64    if err != nil {
65        return nil, err
66    }
67    return resBody, nil
68}

登入後複製

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

看上去貌似沒啥問題吧。

程式碼跑起來，也確實能正常收發訊息。

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

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

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

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

排查

i/o timeout ，希望你不要踩到這個net/http包的坑 — 五層網路協定對應的訊息體變化分析

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

這裡推測有兩個可能。

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

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

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

抓包結果

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

到最后出现超时报错 i/o timeout （画了蓝框的地方）。

从time那一列从7到10，确实间隔3s。而且看右下角的蓝框，是51169端口发到80端口的一次Reset连接。

80端口是服务端的端口。换句话说就是客户端3s超时主动断开链接的。

但是再仔细看下第一行三次握手到最后客户端超时主动断开连接的中间，其实有非常多次HTTP请求。

回去看代码设置超时的方式。

 1    tr = &http.Transport{
 2        MaxIdleConns: 100,
 3        Dial: func(netw, addr string) (net.Conn, error) {
 4            conn, err := net.DialTimeout(netw, addr, time.Second*2) //设置建立连接超时
 5            if err != nil {
 6                return nil, err
 7            }
 8            err = conn.SetDeadline(time.Now().Add(time.Second * 3)) //设置发送接受数据超时
 9            if err != nil {
10                return nil, err
11            }
12            return conn, nil
13        },
14    }

登入後複製

也就是说，这里的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))，并且你用了长连接，哪怕服务端处理再快，客户端设置的超时再长，总有一刻，你的程序会报超时错误。

正确姿势

原本预期是给每次调用设置一个超时，而不是给整个连接设置超时。

另外，上面出现问题的原因是给长连接设置了超时，且长连接会复用。

基于这两点，改一下代码。

 1package main
 2
 3import (
 4    "bytes"
 5    "encoding/json"
 6    "fmt"
 7    "io/ioutil"
 8    "net/http"
 9    "time"
10)
11
12var tr *http.Transport
13
14func init() {
15    tr = &http.Transport{
16        MaxIdleConns: 100,
17        // 下面的代码被干掉了
18        //Dial: func(netw, addr string) (net.Conn, error) {
19        //  conn, err := net.DialTimeout(netw, addr, time.Second*2) //设置建立连接超时
20        //  if err != nil {
21        //      return nil, err
22        //  }
23        //  err = conn.SetDeadline(time.Now().Add(time.Second * 3)) //设置发送接受数据超时
24        //  if err != nil {
25        //      return nil, err
26        //  }
27        //  return conn, nil
28        //},
29    }
30}
31
32
33func Get(url string) ([]byte, error) {
34    m := make(map[string]interface{})
35    data, err := json.Marshal(m)
36    if err != nil {
37        return nil, err
38    }
39    body := bytes.NewReader(data)
40    req, _ := http.NewRequest("Get", url, body)
41    req.Header.Add("content-type", "application/json")
42
43    client := &http.Client{
44        Transport: tr,
45        Timeout: 3*time.Second,  // 超时加在这里，是每次调用的超时
46    }
47    res, err := client.Do(req) 
48    if res != nil {
49        defer res.Body.Close()
50    }
51    if err != nil {
52        return nil, err
53    }
54    resBody, err := ioutil.ReadAll(res.Body)
55    if err != nil {
56        return nil, err
57    }
58    return resBody, nil
59}
60
61func main() {
62    for {
63        _, err := Get("http://www.baidu.com/")
64        if err != nil {
65            fmt.Println(err)
66            break
67        }
68    }
69}

登入後複製

看注释会发现，改动的点有两个

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。

从发起一个网络请求开始跟。

 1res, err := client.Do(req)
 2func (c *Client) Do(req *Request) (*Response, error) {
 3    return c.do(req)
 4}
 5
 6func (c *Client) do(req *Request) {
 7    // ...
 8    if resp, didTimeout, err = c.send(req, deadline); err != nil {
 9    // ...
10  }
11    // ...  
12}  
13func send(ireq *Request, rt RoundTripper, deadline time.Time) {
14    // ...    
15    resp, err = rt.RoundTrip(req)
16     // ...  
17} 
18
19// 从这里进入 RoundTrip 逻辑
20/src/net/http/roundtrip.go: 16
21func (t *Transport) RoundTrip(req *Request) (*Response, error) {
22    return t.roundTrip(req)
23}
24
25func (t *Transport) roundTrip(req *Request) (*Response, error) {
26    // 尝试去获取一个空闲连接，用于发起 http 连接
27  pconn, err := t.getConn(treq, cm)
28  // ...
29}
30
31// 重点关注这个函数，返回是一个长连接
32func (t *Transport) getConn(treq *transportRequest, cm connectMethod) (*persistConn, error) {
33  // 省略了大量逻辑，只关注下面两点
34    // 有空闲连接就返回
35    pc := <-t.getIdleConnCh(cm)
36
37  // 没有创建连接
38  pc, err := t.dialConn(ctx, cm)
39
40}

登入後複製

这里上面很多代码，其实只是为了展示这部分代码是怎么跟踪下来的，方便大家去看源码的时候去跟一下。

最后一个上面的代码里有个 getConn 方法。在发起网络请求的时候，会先取一个网络连接，取连接有两个来源。

如果有空闲连接，就拿空闲连接

1/src/net/http/tansport.go:810
2func (t *Transport) getIdleConnCh(cm connectMethod) chan *persistConn {
3 // 返回放空闲连接的chan
4 ch, ok := t.idleConnCh[key]
5   // ...
6 return ch
7}

登入後複製

没有空闲连接，就创建长连接。

1/src/net/http/tansport.go:1357
2func (t *Transport) dialConn() {
3  //...
4  conn, err := t.dial(ctx, "tcp", cm.addr())
5  // ...
6  go pconn.readLoop()
7  go pconn.writeLoop()
8  // ...
9}

登入後複製

当第一次发起一个http请求时，这时候肯定没有空闲连接，会建立一个新连接。同时会创建一个读goroutine和一个写goroutine。

注意上面代码里的t.dial(ctx, "tcp", cm.addr())，如果像文章开头那样设置了 http.Transport的

 1Dial: func(netw, addr string) (net.Conn, error) {
 2   conn, err := net.DialTimeout(netw, addr, time.Second*2) //设置建立连接超时
 3   if err != nil {
 4      return nil, err
 5   }
 6   err = conn.SetDeadline(time.Now().Add(time.Second * 3)) //设置发送接受数据超时
 7   if err != nil {
 8      return nil, err
 9   }
10   return conn, nil
11},

登入後複製

那么这里就会在下面的dial里被执行到

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

登入後複製

这里面调用的设置超时，会执行到

 1/src/net/net.go
 2func (c *conn) SetDeadline(t time.Time) error {
 3    //...
 4    c.fd.SetDeadline(t)
 5    //...
 6}
 7
 8//...
 9
10func setDeadlineImpl(fd *FD, t time.Time, mode int) error {
11    // ...
12    runtime_pollSetDeadline(fd.pd.runtimeCtx, d, mode)
13    return nil
14}
15
16
17//go:linkname poll_runtime_pollSetDeadline internal/poll.runtime_pollSetDeadline
18func poll_runtime_pollSetDeadline(pd *pollDesc, d int64, mode int) {
19    // ...
20  // 设置一个定时器事件
21  rtf = netpollDeadline
22    // 并将事件注册到定时器里
23  modtimer(&pd.rt, pd.rd, 0, rtf, pd, pd.rseq)
24}

登入後複製

上面的源码，简单来说就是，当第一次调用请求的，会建立个连接，这时候还会注册一个定时器事件，假设时间设了3s，那么这个事件会在3s后发生，然后执行注册事件的逻辑。而这个注册事件就是netpollDeadline。 注意这个netpollDeadline，待会会提到。

设置了超时事件，且超时事件是3s后之后，发生。再次期间正常收发数据。一切如常。

直到3s过后，这时候看读goroutine，会等待网络数据返回。

1/src/net/http/tansport.go:1642
2func (pc *persistConn) readLoop() {
3    //...
4    for alive {
5        _, err := pc.br.Peek(1)  // 阻塞读取服务端返回的数据
6    //...
7}

登入後複製

然后就是一直跟代码。

 1src/bufio/bufio.go: 129
 2func (b *Reader) Peek(n int) ([]byte, error) {
 3   // ...
 4   b.fill() 
 5   // ...   
 6}
 7
 8func (b *Reader) fill() {
 9    // ...
10    n, err := b.rd.Read(b.buf[b.w:])
11    // ...
12}
13
14/src/net/http/transport.go: 1517
15func (pc *persistConn) Read(p []byte) (n int, err error) {
16    // ...
17    n, err = pc.conn.Read(p)
18    // ...
19}
20
21// /src/net/net.go: 173
22func (c *conn) Read(b []byte) (int, error) {
23    // ...
24    n, err := c.fd.Read(b)
25    // ...
26}
27
28func (fd *netFD) Read(p []byte) (n int, err error) {
29    n, err = fd.pfd.Read(p)
30    // ...
31}
32
33/src/internal/poll/fd_unix.go: 
34func (fd *FD) Read(p []byte) (int, error) {
35    //...
36  if err = fd.pd.waitRead(fd.isFile); err == nil {
37    continue
38  }
39    // ...
40}
41
42func (pd *pollDesc) waitRead(isFile bool) error {
43    return pd.wait(&#39;r&#39;, isFile)
44}
45
46func (pd *pollDesc) wait(mode int, isFile bool) error {
47    // ...
48  res := runtime_pollWait(pd.runtimeCtx, mode)
49    return convertErr(res, isFile)
50}

登入後複製

直到跟到 runtime_pollWait，这个可以简单认为是等待服务端数据返回。

 1//go:linkname poll_runtime_pollWait internal/poll.runtime_pollWait
 2func poll_runtime_pollWait(pd *pollDesc, mode int) int {
 3
 4    // 1.如果网络正常返回数据就跳出
 5  for !netpollblock(pd, int32(mode), false) {
 6    // 2.如果有出错情况也跳出
 7        err = netpollcheckerr(pd, int32(mode))
 8        if err != 0 {
 9            return err
10        }
11    }
12    return 0
13}

登入後複製

整条链路跟下来，就是会一直等待数据，等待的结果只有两个

有可以读的数据
出现报错

这里面的报错，又有那么两种

连接关闭
超时

1func netpollcheckerr(pd *pollDesc, mode int32) int {
2    if pd.closing {
3        return 1 // errClosing
4    }
5    if (mode == &#39;r&#39; && pd.rd < 0) || (mode == &#39;w&#39; && pd.wd < 0) {
6        return 2 // errTimeout
7    }
8    return 0
9}

登入後複製

其中提到的超时，就是指这里面返回的数字2，会通过下面的函数，转化为 ErrTimeout，而 ErrTimeout.Error() 其实就是 i/o timeout。

 1func convertErr(res int, isFile bool) error {
 2    switch res {
 3    case 0:
 4        return nil
 5    case 1:
 6        return errClosing(isFile)
 7    case 2:
 8        return ErrTimeout // ErrTimeout.Error() 就是 "i/o timeout"
 9    }
10    println("unreachable: ", res)
11    panic("unreachable")
12}

登入後複製

那么问题来了。上面返回的超时错误，也就是返回2的时候的条件是怎么满足的？

1    if (mode == &#39;r&#39; && pd.rd < 0) || (mode == &#39;w&#39; && pd.wd < 0) {
2        return 2 // errTimeout
3    }

登入後複製

还记得刚刚提到的 netpollDeadline吗？

这里面放了定时器3s到点时执行的逻辑。

 1func timerproc(tb *timersBucket) {
 2    // 计时器到设定时间点了，触发之前注册函数
 3    f(arg, seq) // 之前注册的是 netpollDeadline
 4}
 5
 6func netpollDeadline(arg interface{}, seq uintptr) {
 7    netpolldeadlineimpl(arg.(*pollDesc), seq, true, true)
 8}
 9
10/src/runtime/netpoll.go: 428
11func netpolldeadlineimpl(pd *pollDesc, seq uintptr, read, write bool) {
12    //...
13    if read {
14        pd.rd = -1
15        rg = netpollunblock(pd, &#39;r&#39;, false)
16    }
17    //...
18}

登入後複製

这里会设置pd.rd=-1，是指 poller descriptor.read deadline ，含义网络轮询器文件描述符的读超时时间，我们知道在linux里万物皆文件，这里的文件其实是指这次网络通讯中使用到的socket。

这时候再回去看发生超时的条件就是if (mode == 'r' && pd.rd < 0)。

至此。我们的代码里就收到了 io timeout 的报错。