線上大量CLOSE_WAIT緣由深刻分析

這一次重啓真的沒法解決問題了：一次 MySQL 主動關閉，致使服務出現大量 CLOSE_WAIT 的全流程排查過程。

近日遇到一個線上服務 socket 資源被不斷打滿的狀況。經過各類工具分析線上問題,定位到問題代碼。這裏對該問題發現、修復過程進行一下覆盤總結。

先看兩張圖。一張圖是服務正常時監控到的 socket 狀態，另外一張固然就是異常啦！

圖一：正常時監控

圖二：異常時監控

從圖中的表現狀況來看，就是從 04:00 開始，socket 資源不斷上漲，每一個谷底時重啓後恢復到正常值，而後繼續不斷上漲不釋放，並且每次達到峯值的間隔時間愈來愈短。

重啓後，排查了日誌，沒有看到 panic ，此時也就沒有進一步檢查，真的覺得重啓大法好。

狀況說明

該服務使用Golang開發，已經上線正常運行將近一年，提供給其它服務調用，主要底層資源有DB/Redis/MQ。

爲了後續說明的方便，將服務的架構圖進行一下說明。

圖三：服務架構

架構是很是簡單。

問題出如今早上 08:20 左右開始的，報警收到該服務出現 504，此時第一反應是該服務長時間沒有重啓（快兩個月了），可能存在一些內存泄漏，沒有多想直接進行了重啓。也就是在圖二第一個谷底的時候，通過重啓服務恢復到正常水平（重啓真好用，開心）。

將近 14:00 的時候，再次被告警出現了 504 ，當時心中略感不對勁，但因爲當天剛好有一場大型促銷活動，所以先立馬再次重啓服務。直到後續大概過了1小時後又開始告警，連續幾回重啓後，發現須要重啓的時間間隔愈來愈短。此時發現問題毫不簡單。這一次重啓真的解決不了問題老，所以立馬申請機器權限、開始排查問題。下面的截圖所有來源個人重現demo，與線上無關。

發現問題

出現問題後，首先要進行分析推斷、而後驗證、最後定位修改。根據當時的表現是分別進行了如下猜測。

ps：後續截圖所有來源本身本地復現時的截圖

推斷一

socket 資源被不斷打滿，而且以前從未出現過，今日忽然出現， 懷疑是否是請求量太大壓垮服務

通過查看實時 qps 後，放棄該想法，雖然量有增長，但依然在服務器承受範圍（遠遠未達到壓測的基準值）。

推斷二

兩臺機器故障是同時發生，重啓一臺，另一臺也會獲得緩解，做爲獨立部署在兩個集羣的服務很是詭異

有了上面的的依據，推出的結果是確定是該服務依賴的底層資源除了問題，要否則不可能獨立集羣的服務同時出問題。

因爲監控顯示是 socket 問題，所以經過 netstat 命令查看了當前tcp連接的狀況（本地測試，線上實際值大的多）

/go/src/hello # netstat -na | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'
LISTEN 2
CLOSE_WAIT 23 # 很是異常
TIME_WAIT 1

發現絕大部份的連接處於 CLOSE_WAIT 狀態，這是很是難以想象狀況。而後用 netstat -an 命令進行了檢查。

圖四：大量的CLOSE_WAIT

CLOSED 表示socket鏈接沒被使用。
LISTENING 表示正在監聽進入的鏈接。
SYN_SENT 表示正在試着創建鏈接。
SYN_RECEIVED 進行鏈接初始同步。
ESTABLISHED 表示鏈接已被創建。
CLOSE_WAIT 表示遠程計算器關閉鏈接，正在等待socket鏈接的關閉。
FIN_WAIT_1 表示socket鏈接關閉，正在關閉鏈接。
CLOSING 先關閉本地socket鏈接，而後關閉遠程socket鏈接，最後等待確認信息。
LAST_ACK 遠程計算器關閉後，等待確認信號。
FIN_WAIT_2 socket鏈接關閉後，等待來自遠程計算器的關閉信號。
TIME_WAIT 鏈接關閉後，等待遠程計算器關閉重發。

而後開始重點思考爲何會出現大量的mysql鏈接是 CLOSE_WAIT 呢？爲了說清楚，咱們來插播一點TCP的四次揮手知識。

TCP四次揮手

咱們來看看 TCP 的四次揮手是怎麼樣的流程：

圖五：TCP四次揮手

用中文來描述下這個過程：

Client: 服務端大哥，我事情都幹完了，準備撤了，這裏對應的就是客戶端發了一個FIN

Server：知道了，可是你等等我，我還要收收尾，這裏對應的就是服務端收到 FIN 後迴應的 ACK

通過上面兩步以後，服務端就會處於 CLOSE_WAIT 狀態。過了一段時間 Server 收尾完了

Server：小弟，哥哥我作完了，撤吧，服務端發送了FIN

Client：大哥，再見啊，這裏是客戶端對服務端的一個 ACK

到此服務端就能夠跑路了，可是客戶端還不行。爲何呢？客戶端還必須等待 2MSL 個時間，這裏爲何客戶端還不能直接跑路呢？主要是爲了防止發送出去的 ACK 服務端沒有收到，服務端重發 FIN 再次來詢問，若是客戶端發完就跑路了，那麼服務端重發的時候就沒人理他了。這個等待的時間長度也很講究。

Maximum Segment Lifetime 報文最大生存時間，它是任何報文在網絡上存在的最長時間，超過這個時間報文將被丟棄

這裏必定不要被圖裏的 client／server 和項目裏的客戶端服務器端混淆，你只要記住：主動關閉的一方發出 FIN 包（Client），被動關閉（Server）的一方響應 ACK 包，此時，被動關閉的一方就進入了 CLOSE_WAIT 狀態。若是一切正常，稍後被動關閉的一方也會發出 FIN 包，而後遷移到 LAST_ACK 狀態。

既然是這樣， TCP 抓包分析下：

/go # tcpdump -n port 3306
# 發生了 3次握手
11:38:15.679863 IP 172.18.0.5.38822 > 172.18.0.3.3306: Flags [S], seq 4065722321, win 29200, options [mss 1460,sackOK,TS val 2997352 ecr 0,nop,wscale 7], length 0
11:38:15.679923 IP 172.18.0.3.3306 > 172.18.0.5.38822: Flags [S.], seq 780487619, ack 4065722322, win 28960, options [mss 1460,sackOK,TS val 2997352 ecr 2997352,nop,wscale 7], length 0
11:38:15.679936 IP 172.18.0.5.38822 > 172.18.0.3.3306: Flags [.], ack 1, win 229, options [nop,nop,TS val 2997352 ecr 2997352], length 0

# mysql 主動斷開連接
11:38:45.693382 IP 172.18.0.3.3306 > 172.18.0.5.38822: Flags [F.], seq 123, ack 144, win 227, options [nop,nop,TS val 3000355 ecr 2997359], length 0 # MySQL負載均衡器發送fin包給我
11:38:45.740958 IP 172.18.0.5.38822 > 172.18.0.3.3306: Flags [.], ack 124, win 229, options [nop,nop,TS val 3000360 ecr 3000355], length 0 # 我回復ack給它

... ... # 原本還須要我發送fin給他，可是我沒有發，因此出現了close_wait。那這是什麼緣故呢？

src > dst: flags data-seqno ack window urgent options

src > dst 代表從源地址到目的地址
flags 是TCP包中的標誌信息,S 是SYN標誌, F(FIN), P(PUSH) , R(RST) "."(沒有標記)
data-seqno 是數據包中的數據的順序號
ack 是下次指望的順序號
window 是接收緩存的窗口大小
urgent 代表數據包中是否有緊急指針
options 是選項

結合上面的信息，我用文字說明下：MySQL負載均衡器 給個人服務發送 FIN 包，我進行了響應，此時我進入了 CLOSE_WAIR 狀態，可是後續做爲被動關閉方的我，並無發送 FIN，致使我服務端一直處於 CLOSE_WAIR 狀態，沒法最終進入 CLOSED 狀態。

那麼我推斷出現這種狀況可能的緣由有如下幾種：

1. 負載均衡器 異常退出了，

   這基本是不可能的，他出現問題絕對是大面積的服務報警，而不只僅是我一個服務

2. MySQL負載均衡器 的超時設置的過短了，致使業務代碼尚未處理完，MySQL負載均衡器 就關閉tcp鏈接了

   這也不太可能，由於這個服務並無什麼耗時操做，固然仍是去檢查了負載均衡器的配置，設置的是60s。

3. 代碼問題，MySQL 鏈接沒法釋放

   目前看起來應該是代碼質量問題，加之本次數據有異常，觸發到了之前某個沒有測試到的點，目前看起來頗有多是這個緣由

查找錯誤緣由

因爲代碼的業務邏輯並非我寫的，我擔憂一時半會看不出來問題，因此直接使用 perf 把全部的調用關係使用火焰圖給繪製出來。既然上面咱們推斷代碼中沒有釋放mysql鏈接。無非就是：

1. 確實沒有調用close
2. 有耗時操做（火焰圖能夠很是明顯看到），致使超時了
3. mysql的事務沒有正確處理，例如：rollback 或者 commit

因爲火焰圖包含的內容太多，爲了讓你們看清楚，我把一些沒必要要的信息進行了摺疊。

圖六：有問題的火焰圖

火焰圖很明顯看到了開啓了事務，可是在餘下的部分，並無看到 Commit 或者是Rollback 操做。這確定會操做問題。而後也清楚看到出現問題的是：

MainController.update 方法內部，話很少說，直接到 update 方法中去檢查。發現了以下代碼：

func (c *MainController) update() (flag bool) {
    o := orm.NewOrm()
    o.Using("default")
    
    o.Begin()
    nilMap := getMapNil()
    if nilMap == nil {// 這裏只檢查了是否爲nil，並無進行rollback或者commit
        return false
    }

    nilMap[10] = 1
    nilMap[20] = 2
    if nilMap == nil && len(nilMap) == 0 {
        o.Rollback()
        return false
    }

    sql := "update tb_user set name=%s where id=%d"
    res, err := o.Raw(sql, "Bug", 2).Exec()
    if err == nil {
        num, _ := res.RowsAffected()
        fmt.Println("mysql row affected nums: ", num)
        o.Commit()
        return true
    }

    o.Rollback()
    return false
}

至此，所有分析結束。通過查看 getMapNil 返回了nil，可是下面的判斷條件沒有進行回滾。

if nilMap == nil {
    o.Rollback()// 這裏進行回滾
    return false
}

總結

整個分析過程仍是廢了很多時間。最主要的是主觀意識太強，以爲運行了一年沒有出問題的爲何會忽然出問題？所以一開始是質疑 SRE、DBA、各類基礎設施出了問題（人老是先懷疑別人）。致使在這上面費了很多時間。

理一下正確的分析思路：

1. 出現問題後，立馬應該檢查日誌，確實日誌沒有發現問題；
2. 監控明確顯示了socket不斷增加，很明確立馬應該使用 netstat 檢查狀況看看是哪一個進程的鍋；
3. 根據 netstat 的檢查，使用 tcpdump 抓包分析一下爲何鏈接會被動斷開（TCP知識很是重要）；
4. 若是熟悉代碼應該直接去檢查業務代碼，若是不熟悉則可使用 perf 把代碼的調用鏈路打印出來；
5. 不管是分析代碼仍是火焰圖，到此應該可以很快定位到問題。

那麼本次究竟是爲何會出現 CLOSE_WAIR 呢？大部分同窗應該已經明白了，我這裏再簡單說明一下：

因爲那一行代碼沒有對事務進行回滾，致使服務端沒有主動發起close。所以 MySQL負載均衡器 在達到 60s 的時候主動觸發了close操做，可是經過tcp抓包發現，服務端並無進行迴應，這是由於代碼中的事務沒有處理，所以從而致使大量的端口、鏈接資源被佔用。在貼一下揮手時的抓包數據：

# mysql 主動斷開連接
11:38:45.693382 IP 172.18.0.3.3306 > 172.18.0.5.38822: Flags [F.], seq 123, ack 144, win 227, options [nop,nop,TS val 3000355 ecr 2997359], length 0 # MySQL負載均衡器發送fin包給我
11:38:45.740958 IP 172.18.0.5.38822 > 172.18.0.3.3306: Flags [.], ack 124, win 229, options [nop,nop,TS val 3000360 ecr 3000355], length 0 # 我回復ack給它

但願此文對你們排查線上問題有所幫助。爲了便於幫助你們理解，下面附上正確狀況下的火焰圖與錯誤狀況下的火焰圖。你們能夠自行對比。

• 正確狀況下的火焰圖
• 錯誤狀況的火焰圖

我參考的一篇文章對這種狀況提出了兩個思考題，我以爲很是有意義，你們本身思考下：

1. 爲何一臺機器幾百個 CLOSE_WAIR 就致使不可繼續訪問？咱們不是常常說一臺機器有 65535 個文件描述符可用嗎？
2. 爲何我有負載均衡，而兩臺部署服務的機器確幾乎同時出了 CLOSE_WAIR ?

參考文章：

1. 又見CLOSE_WAIT
2. TCP 4-times close

我的公衆號：dayuTalk