作者： yanhengwang，騰訊 PCG 開發工程師

在 golang 中創建 goroutine 是一件很容易的事情，但是不合理的使用可能會導致大量 goroutine 無法結束，資源也無法被釋放，隨著時間推移造成了內存的泄漏。避免 goroutine 泄漏的關鍵是要合理管理 goroutine 的生命周期，通過導出 runtime 指標和利用 pprof 可以發現和解決 goroutine 泄漏問題。

筆者維護了一個通過 SSH 連接到目標機器并執行命令的服務，這是一個內部小服務，平時沒有問題的時候一般也不會關注。大約 4 個月前，最后一次更新的時候，增加了一個任務計數器并且導出到 prometheus 中監控起來。近期發現這個計數器在穩步增加。

第一反應是，好事！調用量穩步增長了！！但是一想不對啊，這內部小服務哪兒來這么多調用量。于是再看看 goroutine 的監控情況（這個數據從 runtime.NumGoroutine()獲取的）

goroutine 的數量也是穩步增加的，單位時間請求量增加，goroutine 數量也增進，沒毛病。但是又再轉念一想，內部小服務，不可能不可能。

于是再看一下所有請求在 mm 系統的視圖：

可以看出，每 5 分鐘請求量在 2000 左右，平均下來每分鐘 400 的請求量，上面 prometheus 監控圖中，每個曲線是一個實例，實際上部署了 4 個實例，因此 400 還要除以 4 得到單個實例（曲線）的請求量應該在 100/min 左右，在服務剛啟動的時候該計數器也確實在 100/min 左右，隨著時間推移慢慢泄漏了。

Goroutine 泄漏 (Goroutine leak)

雖然心里想著 99%是泄漏了，但是也要看點詳細的信息。之前在服務里已經啟用了 net/http/pprof，因此直接請求 pprof 暴露出來的 HTTP 接口。

#?goroutines摘要 curl?http://service:port/debug/pprof/goroutine?debug=1 #?goroutines詳情 curl?http://service:port/debug/pprof/goroutine?debug=2

先看一下導出的 goroutine 摘要：

有 1000+個 goroutine 處于同一個狀態，簡單看是等待讀數據，再看下導出的 goroutine 詳情：

不看不知道，一看嚇一跳，詳情里有 goroutine 阻塞的時間超過了 20w 分鐘（4 個月）……

可以肯定是 goroutine 泄漏無疑了。為什么會泄漏？只有順著 pprof 導出的 goroutine 信息去排查了。處于 IO wait 狀態最多的這 1000 多 goroutine 的調用棧都打出來了，根據這段調用棧內容來看，找到對應代碼的位置，從 ssh.Dial 開始一直到某個地方進行 io.ReadFull 便阻塞住了。

這個服務進行 ssh 連接使用的是 golang.org/x/crypto/ssh 這個包。先看一下在這個服務里調用 ssh.Dial 的地方：

clientConfig?:=?&ssh.ClientConfig{...Timeout:?3?*?time.Second,... } //?connet?to?ssh client,?err?:=?ssh.Dial("tcp",?fmt.Sprintf("%s:%d",?s.Host,?36000),?clientConfig)

看起來是沒啥問題的，畢竟傳入了一個 Timeout 參數，不應該會阻塞。接著繼續看下去發現了一些問題。直接來到調用棧中阻塞的地方（先不看 library 和 runtime，這兩個一般沒問題），是在進行 SSH Handshake 的第一個步驟，交換 SSH 版本這步。

//?Sends?and?receives?a?version?line.??The?versionLine?string?should //?be?US?ASCII,?start?with?"SSH-2.0-",?and?should?not?include?a //?newline.?exchangeVersions?returns?the?other?side's?version?line. func?exchangeVersions(rw?io.ReadWriter,?versionLine?[]byte)?(them?[]byte,?err?error)?{...if?_,?err?=?rw.Write(append(versionLine,?'\r',?'\n'));?err?!=?nil?{return}them,?err?=?readVersion(rw)return?them,?err }//?maxVersionStringBytes?is?the?maximum?number?of?bytes?that?we'll //?accept?as?a?version?string.?RFC?4253?p?4.2?limits?this?at?255 //?chars const?maxVersionStringBytes?=?255//?Read?version?string?as?specified?by?RFC?4253,?p?4.2. func?readVersion(r?io.Reader)?([]byte,?error)?{versionString?:=?make([]byte,?0,?64)var?ok?boolvar?buf?[1]bytefor?length?:=?0;?length?<?maxVersionStringBytes;?length++?{_,?err?:=?io.ReadFull(r,?buf[:])?//?阻塞在這里if?err?!=?nil?{return?nil,?err}...}...return?versionString,?nil }

看邏輯是在給對端發送完自己的版本信息后，等待對端回復，但是一直沒有收到回復。但是為什么會沒回復，為什么沒有超時，剛開始看到這里的我是懵逼的。我只能想到既然這些都阻塞在等待對端回復上，那么一定有對應的連接存在，我先看看機器上的連接有什么問題。

TCP 連接的半打開狀態 (TCP half-open)

在機器上執行了一下 netstat 命令看了下連接數。

#?netstat?-anp|grep?:36000|awk?'{print?$6}'|sort|uniq?-c2110?ESTABLISHED1?LISTEN41?TIME_WAIT

有大量處于 ESTABLISHED 的進程，數量和 goroutine 數能大致對上。先把注意力放到這些連接上，選其中一兩個看看有什么問題吧。

接著便發現，有些連接，在本機有 6 個連接：

但是，對端一個也沒有（圖上那一個連接是我登錄到目標機器的 ssh 連接）：

google 查了下，發現這種情況屬于 TCP 半打開狀態，出現這種情況應該是建立連接后對端掛掉了或者其他網絡無法連通的原因，而連接又沒有啟動 KeepAlive，導致一端無法發現這種情況，繼續顯示 ESTABLISHED 的連接，而另一端在機器掛掉重新啟動后便不存在這條鏈接了。現在要確認一下是否真的沒用啟用 KeepAlive：

#?ss?-aeon|grep?:36000|grep?-v?time|wc?-l 2110

全部沒開……這里不帶 KeepAlive 的連接數和上面 netstat 顯示出來狀態為 ESTABLISHED 狀態的連接數一致，實際上在執行這兩條命令的間隙肯定有新請求進來，這兩個數字對上不能說完全匹配，只能說大多數是沒有開啟的。這里能 Get 到點就行。

再看一下 ssh.Dial 的邏輯，建立連接用的是 net.DialTimeout，而現網發生泄漏的版本是用 go1.9.2 編譯的，這個版本的 net.DialTimeout 返回的 net.Conn 結構體的 KeepAlive 是默認關閉的(go1.9.2/net/client.go?)。

golang.org/x/crypto/ssh 包在調用 net.DialTimeout 時不會顯式啟用 KeepAlive，完全依賴于當前 go 版本的默認行為。在最新版的 go 里面已經把建立 TCP 連接時啟動 KeepAlive 作為默認行為了，于是這里我把代碼遷移到 go1.13.3 重新編譯了一次發到現網了，以為問題就塵埃落定了。

SSH 握手阻塞 (SSH Handshake hang)

實際上不是的。用 go1.13.3 編譯的版本，運行一段時間后，用 pprof 看 goroutine 情況，還是存在不少處于 IO wait 狀態的，并且看調用棧還是原來的味道（SSH handshake 時交換版本信息）。再看一下機器上的連接情況：

#?netstat?-anp|grep?:36000|awk?'{print?$6}'|sort|uniq?-c81?ESTABLISHED1?LISTEN1?SYN_SENT23?TIME_WAIT #?ss?-aeon|grep?:36000|grep?time|wc?-l 110 #?ss?-aeon|grep?:36000|grep?-v?time|wc?-l 1 #?ss?-aeon|grep?:36000|grep?-v?time LISTEN?????0??????128?????????100.107.1x.x6:36000????????????????????*:*??????ino:2508898466?sk:ffff880a7627ce00

不帶 KeepAlive 那個連接是本機監聽 36000 端口的 sshd，其他都帶上了，那沒什么問題。說明這些阻塞住的應該不是因為 TCP 半打開導致阻塞的，選其中一個 IP 出來看看。

用 telnet 可以連上，但是無法斷開連接。說明 TCP 連接是可以建立的，對端卻因為一些不可知的原因不響應。再看看這個 IP 的連接存在多久了

#?netstat?-atnp|grep?10.100.7x.x9 tcp????????0??????0?100.107.1x.x6:8851????????10.100.7x.x9:36000?????????ESTABLISHED?33027/ssh_tunnel_se #?lsof?-p?33027|grep?10.100.7x.x9 ssh_tunne 33027? mqq? ?16u? IPv4 3069826111? ? ? 0t0? ? ? ? TCP 100-107-1x-x6:8504->10.100.7x.x9:36000 (ESTABLISHED) #?ls?-l?/proc/33027/fd/16 lrwx------?1?mqq?mqq?64?Dec?23?15:44?/proc/33027/fd/16?->?socket:[3069826111]

執行這個命令的時間是 24 日 17 時 25 分，已經阻塞一天多了。那這里的問題就是應用層沒有超時控制導致的。再回過去看 ssh.Dial 的邏輯，Timeout 參數在 SSH handshake 的時候并沒有作為超時控制的參數使用。net.Conn 的 IO 等待在 Linux 下是用非阻塞 epoll_pwait 實現的，進入等待的 goroutine 會被掛起直到有事件進來，超時是通過設置 timer 喚醒 goroutine 進行處理的，暴露出來的接口便是 net.Conn 的 SetDeadline 方法，于是重寫了 ssh.Dial 的邏輯，給 SSH
handshake 階段添加超時：

//?DialTimeout?starts?a?client?connection?to?the?given?SSH?server.?Differ?from //?ssh.Dial?function,?this?function?will?be?timeout?when?doing?SSH?handshake. //?total?timeout?=?(?1?+?timeFactor?)?*?config.Timeout //?refs:?https://github.com/cybozu-go/cke/pull/81/files func?DialTimeout(network,?addr?string,?config?*ssh.ClientConfig)?(*ssh.Client,?error)?{conn,?err?:=?net.DialTimeout(network,?addr,?config.Timeout)if?err?!=?nil?{return?nil,?err}//?set?timeout?for?connectiontimeFactor?:=?time.Duration(3)err?=?conn.SetDeadline(time.Now().Add(config.Timeout?*?timeFactor))if?err?!=?nil?{conn.Close()return?nil,?err}//?do?SSH?handshakec,?chans,?reqs,?err?:=?ssh.NewClientConn(conn,?addr,?config)if?err?!=?nil?{return?nil,?err}//?cancel?connection?read/write?timeouterr?=?conn.SetDeadline(time.Time{})if?err?!=?nil?{conn.Close()return?nil,?err}return?ssh.NewClient(c,?chans,?reqs),?nil }

用這個函數替換了 ssh.Dial 后，編譯上線，看下連接情況，恢復正常了。(恢復到一個小服務應該有的樣子)

#?netstat?-anp|grep?:36000|awk?'{print?$6}'|sort|uniq?-c3?ESTABLISHED1?LISTEN86?TIME_WAIT

到這里會發現，其實本文解決的問題是對端如果出現各種異常了，如何及時關閉連接，而不是去解決對端的異常問題。畢竟 SSH 都異常了，誰還能上去查問題呢。現網服務器數量巨大，運行情況各不相同，因此出現異常也屬情理之中，一一解決不太現實。

結尾

剛開始發現泄漏的時候到機器上 top 看了下，當時被 50G 的 VIRT 占用給嚇著了，在咨詢了組內大佬（zorro）的后，實際上這個值大多數時候都不用關心，只需關心 RES 占用即可。因為 RES 是實際占用的物理內存。

只看這一個時間點的 VIRT 和 RES 也是看不出到底有多少是泄漏的。只能和不同的時間點的內存占用對比，比如解決問題以后的版本，運行了三四天的情況下，VIRT 占用是 3.9G，而 RES 只占用了 16M。這樣比下來看，還是釋放了不少內存。或者說可以見得泄漏的那些 goroutine 占據了多少內存。

在 golang 中創建 goroutine 是一件很容易的事情，但是不合理的使用可能會導致大量 goroutine 無法結束，資源也無法被釋放，隨著時間推移造成了內存的泄漏。

避免 goroutine 泄漏的關鍵是要合理管理 goroutine 的生命周期，通過 prometheus/client_golang 導出 runtime 指標和利用 net/http/pprof 可以發現和解決 goroutine 泄漏問題。

參考

1.Goroutine 泄漏排查

2.一次對 server 服務大量積壓異常 TCP ESTABLISHED 鏈接的排查筆記

總結

以上是生活随笔為你收集整理的一起 goroutine 泄漏问题的排查的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。