golang net-http 超時引發大量 fin-wait2

前言:

通過 grafana 監控面板，發現幾個高頻的業務緩存節點出現了大量的 fin-wait2，而且 fin-wait2 狀態持續了不短的時間。通過連接的 ip 地址及進行抓包數據判斷出對端的業務。除此之外，頻繁的去創建新連接，我們對 golang net/http transport 的連接池已優化過，但 established 已建連的連接沒有得到複用。

另外，隨之帶來的問題是大量 time-wait 的出現，畢竟 fin-wait2 在拿到對端 fin 後會轉變爲 time-wait 狀態。但該狀態是正常的。

分析問題：

通過業務日誌發現了大量的接口超時問題，連接的地址跟 netstat 中 fin-wait2 目的地址是一致的。那麼問題已經明確了，當 http 的請求觸發超時，定時器對連接對象進行了關閉。這邊都 close 了，那麼連接自然無法複用，所以就需要創建新連接，但由於對端的 API 接口出現邏輯阻塞，自然就又觸發了超時，continue。😅

// xiaorui.cc

Get "http://xxxx": context deadline exceeded (Client.Timeout exceeded while awaiting headers)

Get "http://xxxx": context deadline exceeded (Client.Timeout exceeded while awaiting headers)

Get "http://xxxx": context deadline exceeded (Client.Timeout exceeded while awaiting headers)

通過 strace 追蹤 socket 的系統調用，發現 golang 的 socket 讀寫超時沒有使用 setsockopt so_sndtimeo so_revtimeo 參數。

[pid 34262] epoll_ctl(3, EPOLL_CTL_ADD, 6, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=1310076696, u64=140244877192984}}) = 0
[pid 34265] epoll_pwait(3,  <unfinished ...>
[pid 34262] <... getsockname resumed>{sa_family=AF_INET, sin_port=htons(45242), sin_addr=inet_addr("127.0.0.1")}, [112->16]) = 0
[pid 34264] epoll_pwait(3,  <unfinished ...>
[pid 34262] setsockopt(6, SOL_TCP, TCP_NODELAY, [1], 4 <unfinished ...>
[pid 34262] setsockopt(6, SOL_SOCKET, SO_KEEPALIVE, [1], 4 <unfinished ...>
[pid 34264] read(4,  <unfinished ...>
[pid 34262] setsockopt(6, SOL_TCP, TCP_KEEPINTVL, [30], 4 <unfinished ...>

...

代碼分析:

通過 net/http 源碼可以看到 socket 的超時控制是通過定時器來實現的，在連接的 roundTrip 方法看到超時引發關閉連接的邏輯。由於 http 的語義不支持多路複用，所以爲了規避超時後再回來的數據造成混亂，索性直接關閉連接。

當觸發超時會主動關閉連接，這裏涉及到了四次揮手，作爲關閉方會發送 fin，對端內核會迴應 ack，這時候客戶端從 fin-wait1 到 fin-wait2，而服務端在 close-wait 狀態，等待觸發 close syscall 系統調用。服務端什麼時候觸發 close 動作？需要等待 net/http handler 業務邏輯執行完畢。

net/http/transport.go

// xiaorui.cc

var errTimeout error = &httpError{err: "net/http: timeout awaiting response headers", timeout: true}

func (pc *persistConn) roundTrip(req *transportRequest) (resp *Response, err error) {
    for {
        testHookWaitResLoop()
        select {
        case err := <-writeErrCh:
            if debugRoundTrip {
                req.logf("writeErrCh resv: %T/%#v", err, err)
            }
            if err != nil {
                pc.close(fmt.Errorf("write error: %v", err))
                return nil, pc.mapRoundTripError(req, startBytesWritten, err)
            }
            if d := pc.t.ResponseHeaderTimeout; d > 0 {
                if debugRoundTrip {
                    req.logf("starting timer for %v", d)
                }
                timer := time.NewTimer(d)
                defer timer.Stop() // prevent leaks
                respHeaderTimer = timer.C
            }
        case <-pc.closech:
            ...
        case <-respHeaderTimer:
            if debugRoundTrip {
                req.logf("timeout waiting for response headers.")
            }
            pc.close(errTimeout)
            return nil, errTimeout

如何解決？

要麼加大客戶端的超時時間，要麼優化對端的獲取數據的邏輯，總之減少超時的觸發。這個問題跟 golang 是沒有問題，換成 openresyt 和 python 同樣有這個問題。

本文由 Readfog 進行 AMP 轉碼，版權歸原作者所有。
來源：http://xiaorui.cc/archives/6999

猜你喜歡