線上大量CLOSE_WAIT的原因深入分析

大愚Talk發表於2018-12-10
AI

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

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

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

image-20181208155626513

圖一：正常時監控

image-20181208160100456

圖二：異常時監控

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

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

情況說明

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

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

image-20181208162049386

圖三：服務架構

架構是非常簡單。

問題出現在早上 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 命令進行了檢查。

image-20181208172652155

圖四：大量的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 的四次揮手是怎麼樣的流程：

image-20181208175427046

圖五：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_WAIT 狀態，但是後續作為被動關閉方的我，並沒有傳送 FIN，導致我服務端一直處於 CLOSE_WAIT 狀態，無法最終進入 CLOSED 狀態。

那麼我推斷出現這種情況可能的原因有以下幾種：

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

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

  2. MySQL負載均衡器 的超時設定的太短了，導致業務程式碼還沒有處理完，MySQL負載均衡器 就關閉tcp連線了

    這也不太可能，因為這個服務並沒有什麼耗時操作，當然還是去檢查了負載均衡器的配置，設定的是60s。

  3. 程式碼問題，MySQL 連線無法釋放

    目前看起來應該是程式碼質量問題，加之本次資料有異常，觸發到了以前某個沒有測試到的點，目前看起來很有可能是這個原因

查詢錯誤原因

由於程式碼的業務邏輯並不是我寫的，我擔心一時半會看不出來問題，所以直接使用 perf 把所有的呼叫關係使用火焰圖給繪製出來。既然上面我們推斷程式碼中沒有釋放mysql連線。無非就是：

  1. 確實沒有呼叫close
  2. 有耗時操作（火焰圖可以非常明顯看到），導致超時了
  3. mysql的事務沒有正確處理，例如：rollback 或者 commit

由於火焰圖包含的內容太多，為了讓大家看清楚，我把一些不必要的資訊進行了摺疊。

image-20181208212045848

圖六：有問題的火焰圖

火焰圖很明顯看到了開啟了事務，但是在餘下的部分，並沒有看到 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_WAIT 呢？大部分同學應該已經明白了，我這裡再簡單說明一下：

由於那一行程式碼沒有對事務進行回滾，導致服務端沒有主動發起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_WAIT 就導致不可繼續訪問？我們不是經常說一臺機器有 65535 個檔案描述符可用嗎？
  2. 為什麼我有負載均衡，而兩臺部署服務的機器確幾乎同時出了 CLOSE_WAIT ?

參考文章：

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

線上大量CLOSE_WAIT的原因深入分析

個人公眾號：dayuTalk

聯絡郵箱：dayugog@gmail.com

GitHub：github.com/helei112g

線上大量CLOSE_WAIT的原因深入分析

我寫我的，你賞你的

相關文章