python close_wait_线上大量CLOSE_WAIT原因深入分析
這一次重啟真的無法解決問題了：一次 MySQL 主動關閉，導致服務出現(xiàn)大量 CLOSE_WAIT 的全流程排查過程。
近日遇到一個線上服務 socket 資源被不斷打滿的情況。通過各種工具分析線上問題,定位到問題代碼。這里對該問題發(fā)現(xiàn)、修復過程進行一下復盤總結(jié)。
先看兩張圖。一張圖是服務正常時監(jiān)控到的 socket 狀態(tài)，另一張當然就是異常啦！
圖一：正常時監(jiān)控
圖二：異常時監(jiān)控
從圖中的表現(xiàn)情況來看，就是從 04:00 開始，socket 資源不斷上漲，每個谷底時重啟后恢復到正常值，然后繼續(xù)不斷上漲不釋放，而且每次達到峰值的間隔時間越來越短。
重啟后，排查了日志，沒有看到 panic ，此時也就沒有進一步檢查，真的以為重啟大法好。
情況說明
該服務使用Golang開發(fā)，已經(jīng)上線正常運行將近一年，提供給其它服務調(diào)用，主要底層資源有DB/Redis/MQ。
為了后續(xù)說明的方便，將服務的架構(gòu)圖進行一下說明。
圖三：服務架構(gòu)
架構(gòu)是非常簡單。
問題出現(xiàn)在早上 08:20 左右開始的，報警收到該服務出現(xiàn) 504，此時第一反應是該服務長時間沒有重啟(快兩個月了)，可能存在一些內(nèi)存泄漏，沒有多想直接進行了重啟。也就是在圖二第一個谷底的時候，經(jīng)過重啟服務恢復到正常水平(重啟真好用，開心)。
將近 14:00 的時候，再次被告警出現(xiàn)了 504 ，當時心中略感不對勁，但由于當天恰好有一場大型促銷活動，因此先立馬再次重啟服務。直到后續(xù)大概過了1小時后又開始告警，連續(xù)幾次重啟后，發(fā)現(xiàn)需要重啟的時間間隔越來越短。此時發(fā)現(xiàn)問題絕不簡單。這一次重啟真的解決不了問題老，因此立馬申請機器權(quán)限、開始排查問題。下面的截圖全部來源我的重現(xiàn)demo，與線上無關。
發(fā)現(xiàn)問題
出現(xiàn)問題后，首先要進行分析推斷、然后驗證、最后定位修改。根據(jù)當時的表現(xiàn)是分別進行了以下猜想。
ps：后續(xù)截圖全部來源自己本地復現(xiàn)時的截圖
推斷一
socket 資源被不斷打滿，并且之前從未出現(xiàn)過，今日突然出現(xiàn)，懷疑是不是請求量太大壓垮服務
經(jīng)過查看實時 qps 后，放棄該想法，雖然量有增加，但依然在服務器承受范圍(遠遠未達到壓測的基準值)。
推斷二
兩臺機器故障是同時發(fā)生，重啟一臺，另外一臺也會得到緩解，作為獨立部署在兩個集群的服務非常詭異
有了上面的的依據(jù)，推出的結(jié)果是肯定是該服務依賴的底層資源除了問題，要不然不可能獨立集群的服務同時出問題。
由于監(jiān)控顯示是 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
發(fā)現(xiàn)絕大部份的鏈接處于 CLOSE_WAIT 狀態(tài)，這是非常不可思議情況。然后用 netstat -an 命令進行了檢查。
圖四：大量的CLOSE_WAIT
CLOSED 表示socket連接沒被使用。
LISTENING 表示正在監(jiān)聽進入的連接。
SYN_SENT 表示正在試著建立連接。
SYN_RECEIVED 進行連接初始同步。
ESTABLISHED 表示連接已被建立。
CLOSE_WAIT 表示遠程計算器關閉連接，正在等待socket連接的關閉。
FIN_WAIT_1 表示socket連接關閉，正在關閉連接。
CLOSING 先關閉本地socket連接，然后關閉遠程socket連接，最后等待確認信息。
LAST_ACK 遠程計算器關閉后，等待確認信號。
FIN_WAIT_2 socket連接關閉后，等待來自遠程計算器的關閉信號。
TIME_WAIT 連接關閉后，等待遠程計算器關閉重發(fā)。
然后開始重點思考為什么會出現(xiàn)大量的mysql連接是 CLOSE_WAIT 呢？為了說清楚，我們來插播一點TCP的四次揮手知識。
TCP四次揮手
我們來看看 TCP 的四次揮手是怎么樣的流程：
圖五：TCP四次揮手
用中文來描述下這個過程：
Client: 服務端大哥，我事情都干完了，準備撤了，這里對應的就是客戶端發(fā)了一個FIN
Server：知道了，但是你等等我，我還要收收尾，這里對應的就是服務端收到 FIN 后回應的 ACK
經(jīng)過上面兩步之后，服務端就會處于 CLOSE_WAIT 狀態(tài)。過了一段時間 Server 收尾完了
Server：小弟，哥哥我做完了，撤吧，服務端發(fā)送了FIN
Client：大哥，再見啊，這里是客戶端對服務端的一個 ACK
到此服務端就可以跑路了，但是客戶端還不行。為什么呢？客戶端還必須等待 2MSL 個時間，這里為什么客戶端還不能直接跑路呢？主要是為了防止發(fā)送出去的 ACK 服務端沒有收到，服務端重發(fā) FIN 再次來詢問，如果客戶端發(fā)完就跑路了，那么服務端重發(fā)的時候就沒人理他了。這個等待的時間長度也很講究。
Maximum Segment Lifetime 報文最大生存時間，它是任何報文在網(wǎng)絡上存在的最長時間，超過這個時間報文將被丟棄
這里一定不要被圖里的 client／server 和項目里的客戶端服務器端混淆，你只要記住：主動關閉的一方發(fā)出 FIN 包(Client)，被動關閉(Server)的一方響應 ACK 包，此時，被動關閉的一方就進入了 CLOSE_WAIT 狀態(tài)。如果一切正常，稍后被動關閉的一方也會發(fā)出 FIN 包，然后遷移到 LAST_ACK 狀態(tài)。
既然是這樣， TCP 抓包分析下：
/go # tcpdump -n port 3306
# 發(fā)生了 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負載均衡器發(fā)送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給它
... ... # 本來還需要我發(fā)送fin給他，但是我沒有發(fā)，所以出現(xiàn)了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 是數(shù)據(jù)包中的數(shù)據(jù)的順序號
ack 是下次期望的順序號
window 是接收緩存的窗口大小
urgent 表明數(shù)據(jù)包中是否有緊急指針
options 是選項
結(jié)合上面的信息，我用文字說明下：MySQL負載均衡器 給我的服務發(fā)送 FIN 包，我進行了響應，此時我進入了 CLOSE_WAIR 狀態(tài)，但是后續(xù)作為被動關閉方的我，并沒有發(fā)送 FIN，導致我服務端一直處于 CLOSE_WAIR 狀態(tài)，無法最終進入 CLOSED 狀態(tài)。
那么我推斷出現(xiàn)這種情況可能的原因有以下幾種：
負載均衡器 異常退出了，
這基本是不可能的，他出現(xiàn)問題絕對是大面積的服務報警，而不僅僅是我一個服務
MySQL負載均衡器 的超時設置的太短了，導致業(yè)務代碼還沒有處理完，MySQL負載均衡器 就關閉tcp連接了
這也不太可能，因為這個服務并沒有什么耗時操作，當然還是去檢查了負載均衡器的配置，設置的是60s。
代碼問題，MySQL 連接無法釋放
目前看起來應該是代碼質(zhì)量問題，加之本次數(shù)據(jù)有異常，觸發(fā)到了以前某個沒有測試到的點，目前看起來很有可能是這個原因
查找錯誤原因
由于代碼的業(yè)務邏輯并不是我寫的，我擔心一時半會看不出來問題，所以直接使用 perf 把所有的調(diào)用關系使用火焰圖給繪制出來。既然上面我們推斷代碼中沒有釋放mysql連接。無非就是：
確實沒有調(diào)用close
有耗時操作(火焰圖可以非常明顯看到)，導致超時了
mysql的事務沒有正確處理，例如：rollback 或者 commit
由于火焰圖包含的內(nèi)容太多，為了讓大家看清楚，我把一些不必要的信息進行了折疊。
圖六：有問題的火焰圖
火焰圖很明顯看到了開啟了事務，但是在余下的部分，并沒有看到 Commit 或者是Rollback 操作。這肯定會操作問題。然后也清楚看到出現(xiàn)問題的是：
MainController.update 方法內(nèi)部，話不多說，直接到 update 方法中去檢查。發(fā)現(xiàn)了如下代碼：
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
}
至此，全部分析結(jié)束。經(jīng)過查看 getMapNil 返回了nil，但是下面的判斷條件沒有進行回滾。
if nilMap == nil {
o.Rollback()// 這里進行回滾
return false
}
總結(jié)
整個分析過程還是廢了不少時間。最主要的是主觀意識太強，覺得運行了一年沒有出問題的為什么會突然出問題？因此一開始是質(zhì)疑 SRE、DBA、各種基礎設施出了問題(人總是先懷疑別人)。導致在這上面費了不少時間。
理一下正確的分析思路：
出現(xiàn)問題后，立馬應該檢查日志，確實日志沒有發(fā)現(xiàn)問題；
監(jiān)控明確顯示了socket不斷增長，很明確立馬應該使用 netstat 檢查情況看看是哪個進程的鍋；
根據(jù) netstat 的檢查，使用 tcpdump 抓包分析一下為什么連接會被動斷開(TCP知識非常重要)；
如果熟悉代碼應該直接去檢查業(yè)務代碼，如果不熟悉則可以使用 perf 把代碼的調(diào)用鏈路打印出來；
不論是分析代碼還是火焰圖，到此應該能夠很快定位到問題。
那么本次到底是為什么會出現(xiàn) CLOSE_WAIR 呢？大部分同學應該已經(jīng)明白了，我這里再簡單說明一下：
由于那一行代碼沒有對事務進行回滾，導致服務端沒有主動發(fā)起close。因此 MySQL負載均衡器 在達到 60s 的時候主動觸發(fā)了close操作，但是通過tcp抓包發(fā)現(xiàn)，服務端并沒有進行回應，這是因為代碼中的事務沒有處理，因此從而導致大量的端口、連接資源被占用。在貼一下?lián)]手時的抓包數(shù)據(jù)：
# 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負載均衡器發(fā)送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給它
希望此文對大家排查線上問題有所幫助。為了便于幫助大家理解，下面附上正確情況下的火焰圖與錯誤情況下的火焰圖。大家可以自行對比。
我參考的一篇文章對這種情況提出了兩個思考題，我覺得非常有意義，大家自己思考下：
為什么一臺機器幾百個 CLOSE_WAIR 就導致不可繼續(xù)訪問？我們不是經(jīng)常說一臺機器有 65535 個文件描述符可用嗎？
為什么我有負載均衡，而兩臺部署服務的機器確幾乎同時出了 CLOSE_WAIR ?
參考文章：
個人公眾號：dayuTalk
總結(jié)
以上是生活随笔為你收集整理的python close_wait_线上大量CLOSE_WAIT原因深入分析的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： 没有任何基础学编程从哪开始_没有编程基础
- 下一篇： python 作用with_即使__in