本文載自 https://juejin.im/post/5c0cf1ed6fb9a04a08217fcc
這一次重啟真的無法解決問題了：一次 MySQL 主動關(guān)閉，導(dǎo)致服務(wù)出現(xiàn)大量 CLOSE_WAIT 的全流程排查過程。
近日遇到一個線上服務(wù) socket 資源被不斷打滿的情況鲫凶。通過各種工具分析線上問題,定位到問題代碼玻驻。這里對該問題發(fā)現(xiàn)竹捉、修復(fù)過程進(jìn)行一下復(fù)盤總結(jié)违帆。
先看兩張圖挣磨。一張圖是服務(wù)正常時監(jiān)控到的 socket 狀態(tài)豪直，另一張當(dāng)然就是異常啦劣摇！
從圖中的表現(xiàn)情況來看，就是從 04:00 開始弓乙，socket 資源不斷上漲末融，每個谷底時重啟后恢復(fù)到正常值，然后繼續(xù)不斷上漲不釋放暇韧，而且每次達(dá)到峰值的間隔時間越來越短勾习。
重啟后，排查了日志懈玻，沒有看到 panic 巧婶，此時也就沒有進(jìn)一步檢查，真的以為重啟大法好涂乌。
情況說明
該服務(wù)使用Golang開發(fā)粹舵，已經(jīng)上線正常運(yùn)行將近一年，提供給其它服務(wù)調(diào)用骂倘，主要底層資源有DB/Redis/MQ眼滤。
為了后續(xù)說明的方便，將服務(wù)的架構(gòu)圖進(jìn)行一下說明历涝。
架構(gòu)是非常簡單诅需。
問題出現(xiàn)在早上 08:20 左右開始的，報警收到該服務(wù)出現(xiàn) 504荧库，此時第一反應(yīng)是該服務(wù)長時間沒有重啟（快兩個月了）堰塌，可能存在一些內(nèi)存泄漏，沒有多想直接進(jìn)行了重啟分衫。也就是在圖二第一個谷底的時候场刑，經(jīng)過重啟服務(wù)恢復(fù)到正常水平（重啟真好用，開心）蚪战。
將近 14:00 的時候牵现，再次被告警出現(xiàn)了 504 ，當(dāng)時心中略感不對勁邀桑，但由于當(dāng)天恰好有一場大型促銷活動瞎疼，因此先立馬再次重啟服務(wù)。直到后續(xù)大概過了1小時后又開始告警壁畸，連續(xù)幾次重啟后贼急，發(fā)現(xiàn)需要重啟的時間間隔越來越短茅茂。此時發(fā)現(xiàn)問題絕不簡單。這一次重啟真的解決不了問題老太抓，因此立馬申請機(jī)器權(quán)限空闲、開始排查問題。下面的截圖全部來源我的重現(xiàn)demo走敌，與線上無關(guān)进副。
發(fā)現(xiàn)問題
出現(xiàn)問題后，首先要進(jìn)行分析推斷悔常、然后驗(yàn)證影斑、最后定位修改。根據(jù)當(dāng)時的表現(xiàn)是分別進(jìn)行了以下猜想机打。
ps：后續(xù)截圖全部來源自己本地復(fù)現(xiàn)時的截圖
推斷一
socket 資源被不斷打滿矫户，并且之前從未出現(xiàn)過，今日突然出現(xiàn)残邀，懷疑是不是請求量太大壓垮服務(wù)
經(jīng)過查看實(shí)時 qps 后皆辽，放棄該想法，雖然量有增加芥挣，但依然在服務(wù)器承受范圍（遠(yuǎn)遠(yuǎn)未達(dá)到壓測的基準(zhǔn)值）驱闷。
推斷二
兩臺機(jī)器故障是同時發(fā)生，重啟一臺空免，另外一臺也會得到緩解空另，作為獨(dú)立部署在兩個集群的服務(wù)非常詭異
有了上面的的依據(jù)，推出的結(jié)果是肯定是該服務(wù)依賴的底層資源除了問題蹋砚，要不然不可能獨(dú)立集群的服務(wù)同時出問題扼菠。
由于監(jiān)控顯示是 socket 問題，因此通過 netstat 命令查看了當(dāng)前tcp鏈接的情況（本地測試坝咐，線上實(shí)際值大的多）
/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ù)制代碼
發(fā)現(xiàn)絕大部份的鏈接處于 CLOSE_WAIT 狀態(tài)循榆，這是非常不可思議情況。然后用 netstat -an 命令進(jìn)行了檢查墨坚。
CLOSED 表示socket連接沒被使用秧饮。 LISTENING 表示正在監(jiān)聽進(jìn)入的連接。 SYN_SENT 表示正在試著建立連接泽篮。 SYN_RECEIVED 進(jìn)行連接初始同步盗尸。 ESTABLISHED 表示連接已被建立。 CLOSE_WAIT 表示遠(yuǎn)程計(jì)算器關(guān)閉連接咪辱，正在等待socket連接的關(guān)閉振劳。 FIN_WAIT_1 表示socket連接關(guān)閉，正在關(guān)閉連接油狂。 CLOSING 先關(guān)閉本地socket連接，然后關(guān)閉遠(yuǎn)程socket連接，最后等待確認(rèn)信息专筷。 LAST_ACK 遠(yuǎn)程計(jì)算器關(guān)閉后弱贼，等待確認(rèn)信號。 FIN_WAIT_2 socket連接關(guān)閉后磷蛹，等待來自遠(yuǎn)程計(jì)算器的關(guān)閉信號吮旅。 TIME_WAIT 連接關(guān)閉后，等待遠(yuǎn)程計(jì)算器關(guān)閉重發(fā)味咳。
然后開始重點(diǎn)思考為什么會出現(xiàn)大量的mysql連接是 CLOSE_WAIT 呢庇勃？為了說清楚，我們來插播一點(diǎn)TCP的四次揮手知識槽驶。
TCP四次揮手
我們來看看 TCP 的四次揮手是怎么樣的流程：
用中文來描述下這個過程：
Client: 服務(wù)端大哥责嚷，我事情都干完了，準(zhǔn)備撤了掂铐，這里對應(yīng)的就是客戶端發(fā)了一個FIN
Server：知道了罕拂，但是你等等我，我還要收收尾全陨，這里對應(yīng)的就是服務(wù)端收到 FIN 后回應(yīng)的 ACK
經(jīng)過上面兩步之后爆班，服務(wù)端就會處于 CLOSE_WAIT 狀態(tài)。過了一段時間 Server 收尾完了
Server：小弟辱姨，哥哥我做完了柿菩，撤吧，服務(wù)端發(fā)送了FIN
Client：大哥雨涛，再見啊碗旅，這里是客戶端對服務(wù)端的一個 ACK
到此服務(wù)端就可以跑路了，但是客戶端還不行镜悉。為什么呢祟辟？客戶端還必須等待 2MSL 個時間，這里為什么客戶端還不能直接跑路呢侣肄？主要是為了防止發(fā)送出去的 ACK 服務(wù)端沒有收到旧困，服務(wù)端重發(fā) FIN 再次來詢問，如果客戶端發(fā)完就跑路了稼锅，那么服務(wù)端重發(fā)的時候就沒人理他了吼具。這個等待的時間長度也很講究。
Maximum Segment Lifetime 報文最大生存時間矩距，它是任何報文在網(wǎng)絡(luò)上存在的最長時間拗盒，超過這個時間報文將被丟棄
這里一定不要被圖里的 client／server 和項(xiàng)目里的客戶端服務(wù)器端混淆，你只要記鬃墩：主動關(guān)閉的一方發(fā)出 FIN 包（Client）陡蝇，被動關(guān)閉（Server）的一方響應(yīng) ACK 包痊臭，此時，被動關(guān)閉的一方就進(jìn)入了 CLOSE_WAIT 狀態(tài)登夫。如果一切正常广匙，稍后被動關(guān)閉的一方也會發(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ù)載均衡器發(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 # 我回復(fù)ack給它
... ... # 本來還需要我發(fā)送fin給他膀值，但是我沒有發(fā)周循，所以出現(xiàn)了close_wait。那這是什么緣故呢？
復(fù)制代碼
src > dst: flags data-seqno ack window urgent options
src > dst 表明從源地址到目的地址 flags 是TCP包中的標(biāo)志信息,S 是SYN標(biāo)志, F(FIN), P(PUSH) , R(RST) "."(沒有標(biāo)記) data-seqno 是數(shù)據(jù)包中的數(shù)據(jù)的順序號 ack 是下次期望的順序號 window 是接收緩存的窗口大小 urgent 表明數(shù)據(jù)包中是否有緊急指針 options 是選項(xiàng)
結(jié)合上面的信息，我用文字說明下：MySQL負(fù)載均衡器 給我的服務(wù)發(fā)送 FIN 包，我進(jìn)行了響應(yīng)绽乔，此時我進(jìn)入了 CLOSE_WAIT 狀態(tài)，但是后續(xù)作為被動關(guān)閉方的我情龄，并沒有發(fā)送 FIN迄汛，導(dǎo)致我服務(wù)端一直處于 CLOSE_WAIT 狀態(tài)，無法最終進(jìn)入 CLOSED 狀態(tài)骤视。
那么我推斷出現(xiàn)這種情況可能的原因有以下幾種：
-
負(fù)載均衡器 異常退出了鞍爱，
這基本是不可能的，他出現(xiàn)問題絕對是大面積的服務(wù)報警专酗，而不僅僅是我一個服務(wù) -
MySQL負(fù)載均衡器 的超時設(shè)置的太短了睹逃，導(dǎo)致業(yè)務(wù)代碼還沒有處理完，MySQL負(fù)載均衡器 就關(guān)閉tcp連接了
這也不太可能祷肯，因?yàn)檫@個服務(wù)并沒有什么耗時操作沉填，當(dāng)然還是去檢查了負(fù)載均衡器的配置，設(shè)置的是60s佑笋。 -
代碼問題翼闹，MySQL 連接無法釋放
目前看起來應(yīng)該是代碼質(zhì)量問題，加之本次數(shù)據(jù)有異常蒋纬，觸發(fā)到了以前某個沒有測試到的點(diǎn)猎荠，目前看起來很有可能是這個原因
查找錯誤原因
由于代碼的業(yè)務(wù)邏輯并不是我寫的，我擔(dān)心一時半會看不出來問題蜀备，所以直接使用 perf 把所有的調(diào)用關(guān)系使用火焰圖給繪制出來关摇。既然上面我們推斷代碼中沒有釋放mysql連接。無非就是：
- 確實(shí)沒有調(diào)用close
- 有耗時操作（火焰圖可以非常明顯看到）碾阁，導(dǎo)致超時了
- mysql的事務(wù)沒有正確處理输虱，例如：rollback 或者 commit
由于火焰圖包含的內(nèi)容太多，為了讓大家看清楚脂凶，我把一些不必要的信息進(jìn)行了折疊宪睹。
火焰圖很明顯看到了開啟了事務(wù)愁茁，但是在余下的部分，并沒有看到 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食听，并沒有進(jìn)行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
}
復(fù)制代碼
至此胸蛛，全部分析結(jié)束。經(jīng)過查看 getMapNil 返回了nil樱报，但是下面的判斷條件沒有進(jìn)行回滾葬项。
if nilMap == nil {
o.Rollback()// 這里進(jìn)行回滾
return false
}
復(fù)制代碼
總結(jié)
整個分析過程還是廢了不少時間。最主要的是主觀意識太強(qiáng)迹蛤，覺得運(yùn)行了一年沒有出問題的為什么會突然出問題民珍？因此一開始是質(zhì)疑 SRE、DBA盗飒、各種基礎(chǔ)設(shè)施出了問題（人總是先懷疑別人）嚷量。導(dǎo)致在這上面費(fèi)了不少時間。
理一下正確的分析思路：
- 出現(xiàn)問題后逆趣，立馬應(yīng)該檢查日志蝶溶，確實(shí)日志沒有發(fā)現(xiàn)問題；
- 監(jiān)控明確顯示了socket不斷增長宣渗，很明確立馬應(yīng)該使用
netstat檢查情況看看是哪個進(jìn)程的鍋抖所； - 根據(jù)
netstat的檢查，使用tcpdump抓包分析一下為什么連接會被動斷開（TCP知識非常重要）痕囱； - 如果熟悉代碼應(yīng)該直接去檢查業(yè)務(wù)代碼田轧，如果不熟悉則可以使用
perf把代碼的調(diào)用鏈路打印出來； - 不論是分析代碼還是火焰圖鞍恢，到此應(yīng)該能夠很快定位到問題傻粘。
那么本次到底是為什么會出現(xiàn) CLOSE_WAIT 呢？大部分同學(xué)應(yīng)該已經(jīng)明白了有序，我這里再簡單說明一下：
由于那一行代碼沒有對事務(wù)進(jìn)行回滾抹腿，導(dǎo)致服務(wù)端沒有主動發(fā)起close。因此 MySQL負(fù)載均衡器 在達(dá)到 60s 的時候主動觸發(fā)了close操作旭寿，但是通過tcp抓包發(fā)現(xiàn)警绩，服務(wù)端并沒有進(jìn)行回應(yīng)，這是因?yàn)榇a中的事務(wù)沒有處理盅称，因此從而導(dǎo)致大量的端口肩祥、連接資源被占用后室。在貼一下?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ù)載均衡器發(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 # 我回復(fù)ack給它
復(fù)制代碼
希望此文對大家排查線上問題有所幫助。為了便于幫助大家理解混狠，下面附上正確情況下的火焰圖與錯誤情況下的火焰圖岸霹。大家可以自行對比。
我參考的一篇文章對這種情況提出了兩個思考題将饺，我覺得非常有意義贡避，大家自己思考下：
- 為什么一臺機(jī)器幾百個 CLOSE_WAIT 就導(dǎo)致不可繼續(xù)訪問？我們不是經(jīng)常說一臺機(jī)器有 65535 個文件描述符可用嗎予弧？
- 為什么我有負(fù)載均衡刮吧，而兩臺部署服務(wù)的機(jī)器確幾乎同時出了 CLOSE_WAIT ?
參考文章：
作者：大愚Talk
鏈接：https://juejin.im/post/5c0cf1ed6fb9a04a08217fcc
來源：掘金
著作權(quán)歸作者所有。商業(yè)轉(zhuǎn)載請聯(lián)系作者獲得授權(quán)掖蛤，非商業(yè)轉(zhuǎn)載請注明出處杀捻。
