tft每日頭條

 > 圖文

 > 線程wait時是什麼狀态

線程wait時是什麼狀态

圖文 更新时间:2025-02-21 10:05:38
linux服務器開發相關視頻解析:

tcp專題訓練營之深度解析tcp/ip協議棧

10道經典面試題的剖析, 技術方向如何決定職業方向

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

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

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

線程wait時是什麼狀态(WAIT的原因深入分析)1

圖一:正常時監控

線程wait時是什麼狀态(WAIT的原因深入分析)2

圖二:異常時監控

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

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

情況說明

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

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

線程wait時是什麼狀态(WAIT的原因深入分析)3

圖三:服務架構

架構是非常簡單。 問題出現在早上 08:20 左右開始的,報警收到該服務出現 504,此時第一反應是該服務長時間沒有重啟(快兩個月了),可能存在一些内存洩漏,沒有多想直接進行了重啟。也就是在圖二第一個谷底的時候,經過重啟服務恢複到正常水平(重啟真好用,開心)。

将近 14:00 的時候,再次被告警出現了 504 ,當時心中略感不對勁,但由于當天恰好有一場大型促銷活動,因此先立馬再次重啟服務。直到後續大概過了1小時後又開始告警,連續幾次重啟後,發現需要重啟的時間間隔越來越短。此時發現問題絕不簡單。這一次重啟真的解決不了問題老,因此立馬申請機器權限、開始排查問題。下面的截圖全部來源我的重現demo,與線上無關。

發現問題

出現問題後,首先要進行分析推斷、然後驗證、最後定位修改。根據當時的表現是分别進行了以下猜想。

推斷一

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命令進行了檢查。

線程wait時是什麼狀态(WAIT的原因深入分析)4

圖四:大量的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的四次揮手知識。

【文章福利】需要C/C Linux服務器架構師學習資料加群812855908(資料包括C/C ,Linux,golang技術,Nginx,ZeroMQ,MySQL,Redis,fastdfs,MongoDB,ZK,流媒體,CDN,P2P,K8S,Docker,TCP/IP,協程,DPDK,ffmpeg等)

線程wait時是什麼狀态(WAIT的原因深入分析)5

TCP四次揮手

我們來看看tcp的四次揮手是怎麼樣的流程:

線程wait時是什麼狀态(WAIT的原因深入分析)6

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

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

由于火焰圖包含的内容太多,為了讓大家看清楚,我把一些不必要的信息進行了折疊。

線程wait時是什麼狀态(WAIT的原因深入分析)7

圖五:有問題的火焰圖

火焰圖很明顯看到了開啟了事務,但是在餘下的部分,并沒有看到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給它

希望此文對大家排查線上問題有所幫助。為了便于幫助大家理解,下面附上正确情況下的火焰圖與錯誤情況下的火焰圖。大家可以自行對比。

線程wait時是什麼狀态(WAIT的原因深入分析)8

正确的火焰圖

線程wait時是什麼狀态(WAIT的原因深入分析)9

錯誤的火焰圖

這裡提出兩個思考題,我覺得非常有意義,大家自己思考下:

  1. 為什麼一台機器幾百個 CLOSE_WAIT 就導緻不可繼續訪問?我們不是經常說一台機器有 65535 個文件描述符可用嗎?
  2. 為什麼我有負載均衡,而兩台部署服務的機器确幾乎同時出了 CLOSE_WAIT ?
,

更多精彩资讯请关注tft每日頭條,我们将持续为您更新最新资讯!

查看全部

相关圖文资讯推荐

热门圖文资讯推荐

网友关注

Copyright 2023-2025 - www.tftnews.com All Rights Reserved