在 golang 中創(chuàng)建 goroutine 是一件很容易的事情，但是不合理的使用可能會(huì)導(dǎo)致大量 goroutine 無(wú)法結(jié)束，資源也無(wú)法被釋放，隨著時(shí)間推移造成了內(nèi)存的泄漏。避免 goroutine 泄漏的關(guān)鍵是要合理管理 goroutine 的生命周期，通過(guò)導(dǎo)出 runtime 指標(biāo)和利用 pprof 可以發(fā)現(xiàn)和解決 goroutine 泄漏問(wèn)題。

[[311742]]

筆者維護(hù)了一個(gè)通過(guò) SSH 連接到目標(biāo)機(jī)器并執(zhí)行命令的服務(wù)，這是一個(gè)內(nèi)部小服務(wù)，平時(shí)沒(méi)有問(wèn)題的時(shí)候一般也不會(huì)關(guān)注。大約 4 個(gè)月前，最后一次更新的時(shí)候，增加了一個(gè)任務(wù)計(jì)數(shù)器并且導(dǎo)出到 prometheus 中監(jiān)控起來(lái)。近期發(fā)現(xiàn)這個(gè)計(jì)數(shù)器在穩(wěn)步增加。

第一反應(yīng)是，好事!調(diào)用量穩(wěn)步增長(zhǎng)了!!但是一想不對(duì)啊，這內(nèi)部小服務(wù)哪兒來(lái)這么多調(diào)用量。于是再看看 goroutine 的監(jiān)控情況(這個(gè)數(shù)據(jù)從 runtime.NumGoroutine()獲取的)

goroutine 的數(shù)量也是穩(wěn)步增加的，單位時(shí)間請(qǐng)求量增加，goroutine 數(shù)量也增進(jìn)，沒(méi)毛病。但是又再轉(zhuǎn)念一想，內(nèi)部小服務(wù)，不可能不可能。

于是再看一下所有請(qǐng)求在 mm 系統(tǒng)的視圖：

可以看出，每 5 分鐘請(qǐng)求量在 2000 左右，平均下來(lái)每分鐘 400 的請(qǐng)求量，上面 prometheus 監(jiān)控圖中，每個(gè)曲線是一個(gè)實(shí)例，實(shí)際上部署了 4 個(gè)實(shí)例，因此 400 還要除以 4 得到單個(gè)實(shí)例(曲線)的請(qǐng)求量應(yīng)該在 100/min 左右，在服務(wù)剛啟動(dòng)的時(shí)候該計(jì)數(shù)器也確實(shí)在 100/min 左右，隨著時(shí)間推移慢慢泄漏了。

Goroutine 泄漏 (Goroutine leak)

雖然心里想著 99%是泄漏了，但是也要看點(diǎn)詳細(xì)的信息。之前在服務(wù)里已經(jīng)啟用了 net/http/pprof，因此直接請(qǐng)求 pprof 暴露出來(lái)的 HTTP 接口。

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

先看一下導(dǎo)出的 goroutine 摘要：

有 1000+個(gè) goroutine 處于同一個(gè)狀態(tài)，簡(jiǎn)單看是等待讀數(shù)據(jù)，再看下導(dǎo)出的 goroutine 詳情：

不看不知道，一看嚇一跳，詳情里有 goroutine 阻塞的時(shí)間超過(guò)了 20w 分鐘(4 個(gè)月)……

可以肯定是 goroutine 泄漏無(wú)疑了。為什么會(huì)泄漏?只有順著 pprof 導(dǎo)出的 goroutine 信息去排查了。處于 IO wait 狀態(tài)最多的這 1000 多 goroutine 的調(diào)用棧都打出來(lái)了，根據(jù)這段調(diào)用棧內(nèi)容來(lái)看，找到對(duì)應(yīng)代碼的位置，從 ssh.Dial 開(kāi)始一直到某個(gè)地方進(jìn)行 io.ReadFull 便阻塞住了。

這個(gè)服務(wù)進(jìn)行 ssh 連接使用的是 golang.org/x/crypto/ssh 這個(gè)包。先看一下在這個(gè)服務(wù)里調(diào)用 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) 

看起來(lái)是沒(méi)啥問(wèn)題的，畢竟傳入了一個(gè) Timeout 參數(shù)，不應(yīng)該會(huì)阻塞。接著繼續(xù)看下去發(fā)現(xiàn)了一些問(wèn)題。直接來(lái)到調(diào)用棧中阻塞的地方(先不看 library 和 runtime，這兩個(gè)一般沒(méi)問(wèn)題)，是在進(jìn)行 SSH Handshake 的第一個(gè)步驟，交換 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 section 4.2 limits this at 255 
// chars 
const maxVersionStringBytes = 255 
 
// Read version string as specified by RFC 4253, section 4.2. 
func readVersion(r io.Reader) ([]byte, error) { 
    versionString := make([]byte, 0, 64) 
    var ok bool 
    var buf [1]byte 
 
    for length := 0; length < maxVersionStringBytes; length++ { 
        _, err := io.ReadFull(r, buf[:]) // 阻塞在這里 
        if err != nil { 
            return nil, err 
        } 
        ... 
    } 
 
    ... 
    return versionString, nil 
} 

看邏輯是在給對(duì)端發(fā)送完自己的版本信息后，等待對(duì)端回復(fù)，但是一直沒(méi)有收到回復(fù)。但是為什么會(huì)沒(méi)回復(fù)，為什么沒(méi)有超時(shí)，剛開(kāi)始看到這里的我是懵逼的。我只能想到既然這些都阻塞在等待對(duì)端回復(fù)上，那么一定有對(duì)應(yīng)的連接存在，我先看看機(jī)器上的連接有什么問(wèn)題。

TCP 連接的半打開(kāi)狀態(tài) (TCP half-open)

在機(jī)器上執(zhí)行了一下 netstat 命令看了下連接數(shù)。

# netstat -anp|grep :36000|awk '{print $6}'|sort|uniq -c 
 2110 ESTABLISHED 
      1 LISTEN 
     41 TIME_WAIT 

有大量處于 ESTABLISHED 的進(jìn)程，數(shù)量和 goroutine 數(shù)能大致對(duì)上。先把注意力放到這些連接上，選其中一兩個(gè)看看有什么問(wèn)題吧。

接著便發(fā)現(xiàn)，有些連接，在本機(jī)有 6 個(gè)連接：

但是，對(duì)端一個(gè)也沒(méi)有(圖上那一個(gè)連接是我登錄到目標(biāo)機(jī)器的 ssh 連接)：

google 查了下，發(fā)現(xiàn)這種情況屬于 TCP 半打開(kāi)狀態(tài)，出現(xiàn)這種情況應(yīng)該是建立連接后對(duì)端掛掉了或者其他網(wǎng)絡(luò)無(wú)法連通的原因，而連接又沒(méi)有啟動(dòng) KeepAlive，導(dǎo)致一端無(wú)法發(fā)現(xiàn)這種情況，繼續(xù)顯示 ESTABLISHED 的連接，而另一端在機(jī)器掛掉重新啟動(dòng)后便不存在這條鏈接了?，F(xiàn)在要確認(rèn)一下是否真的沒(méi)用啟用 KeepAlive：

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

全部沒(méi)開(kāi)……這里不帶 KeepAlive 的連接數(shù)和上面 netstat 顯示出來(lái)狀態(tài)為 ESTABLISHED 狀態(tài)的連接數(shù)一致，實(shí)際上在執(zhí)行這兩條命令的間隙肯定有新請(qǐng)求進(jìn)來(lái)，這兩個(gè)數(shù)字對(duì)上不能說(shuō)完全匹配，只能說(shuō)大多數(shù)是沒(méi)有開(kāi)啟的。這里能 Get 到點(diǎn)就行。

再看一下 ssh.Dial 的邏輯，建立連接用的是 net.DialTimeout，而現(xiàn)網(wǎng)發(fā)生泄漏的版本是用 go1.9.2 編譯的，這個(gè)版本的 net.DialTimeout 返回的 net.Conn 結(jié)構(gòu)體的 KeepAlive 是默認(rèn)關(guān)閉的(go1.9.2/net/client.go )。

golang.org/x/crypto/ssh 包在調(diào)用 net.DialTimeout 時(shí)不會(huì)顯式啟用 KeepAlive，完全依賴(lài)于當(dāng)前 go 版本的默認(rèn)行為。在最新版的 go 里面已經(jīng)把建立 TCP 連接時(shí)啟動(dòng) KeepAlive 作為默認(rèn)行為了，于是這里我把代碼遷移到 go1.13.3 重新編譯了一次發(fā)到現(xiàn)網(wǎng)了，以為問(wèn)題就塵埃落定了。

SSH 握手阻塞 (SSH Handshake hang)

實(shí)際上不是的。用 go1.13.3 編譯的版本，運(yùn)行一段時(shí)間后，用 pprof 看 goroutine 情況，還是存在不少處于 IO wait 狀態(tài)的，并且看調(diào)用棧還是原來(lái)的味道(SSH handshake 時(shí)交換版本信息)。再看一下機(jī)器上的連接情況：

# netstat -anp|grep :36000|awk '{print $6}'|sort|uniq -c 
     81 ESTABLISHED 
      1 LISTEN 
      1 SYN_SENT 
     23 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 s 

不帶 KeepAlive 那個(gè)連接是本機(jī)監(jiān)聽(tīng) 36000 端口的 sshd，其他都帶上了，那沒(méi)什么問(wèn)題。說(shuō)明這些阻塞住的應(yīng)該不是因?yàn)?TCP 半打開(kāi)導(dǎo)致阻塞的，選其中一個(gè) IP 出來(lái)看看。

用 telnet 可以連上，但是無(wú)法斷開(kāi)連接。說(shuō)明 TCP 連接是可以建立的，對(duì)端卻因?yàn)橐恍┎豢芍脑虿豁憫?yīng)。再看看這個(gè) 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] 

執(zhí)行這個(gè)命令的時(shí)間是 24 日 17 時(shí) 25 分，已經(jīng)阻塞一天多了。那這里的問(wèn)題就是應(yīng)用層沒(méi)有超時(shí)控制導(dǎo)致的。再回過(guò)去看 ssh.Dial 的邏輯，Timeout 參數(shù)在 SSH handshake 的時(shí)候并沒(méi)有作為超時(shí)控制的參數(shù)使用。net.Conn 的 IO 等待在 Linux 下是用非阻塞 epoll_pwait 實(shí)現(xiàn)的，進(jìn)入等待的 goroutine 會(huì)被掛起直到有事件進(jìn)來(lái)，超時(shí)是通過(guò)設(shè)置 timer 喚醒 goroutine 進(jìn)行處理的，暴露出來(lái)的接口便是 net.Conn 的 SetDeadline 方法，于是重寫(xiě)了 ssh.Dial 的邏輯，給 SSH

handshake 階段添加超時(shí)：

// 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 connection 
    timeFactor := time.Duration(3) 
    err = conn.SetDeadline(time.Now().Add(config.Timeout * timeFactor)) 
    if err != nil { 
        conn.Close() 
        return nil, err 
    } 
 
    // do SSH handshake 
    c, chans, reqs, err := ssh.NewClientConn(conn, addr, config) 
    if err != nil { 
        return nil, err 
    } 
 
    // cancel connection read/write timeout 
    err = conn.SetDeadline(time.Time{}) 
    if err != nil { 
        conn.Close() 
        return nil, err 
    } 
    return ssh.NewClient(c, chans, reqs), nil 
} 

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

# netstat -anp|grep :36000|awk '{print $6}'|sort|uniq -c 
      3 ESTABLISHED 
      1 LISTEN 
     86 TIME_WAIT 

到這里會(huì)發(fā)現(xiàn)，其實(shí)本文解決的問(wèn)題是對(duì)端如果出現(xiàn)各種異常了，如何及時(shí)關(guān)閉連接，而不是去解決對(duì)端的異常問(wèn)題。畢竟 SSH 都異常了，誰(shuí)還能上去查問(wèn)題呢。現(xiàn)網(wǎng)服務(wù)器數(shù)量巨大，運(yùn)行情況各不相同，因此出現(xiàn)異常也屬情理之中，一一解決不太現(xiàn)實(shí)。

結(jié)尾

剛開(kāi)始發(fā)現(xiàn)泄漏的時(shí)候到機(jī)器上 top 看了下，當(dāng)時(shí)被 50G 的 VIRT 占用給嚇著了，在咨詢了組內(nèi)大佬(zorro)的后，實(shí)際上這個(gè)值大多數(shù)時(shí)候都不用關(guān)心，只需關(guān)心 RES 占用即可。因?yàn)?RES 是實(shí)際占用的物理內(nèi)存。

只看這一個(gè)時(shí)間點(diǎn)的 VIRT 和 RES 也是看不出到底有多少是泄漏的。只能和不同的時(shí)間點(diǎn)的內(nèi)存占用對(duì)比，比如解決問(wèn)題以后的版本，運(yùn)行了三四天的情況下，VIRT 占用是 3.9G，而 RES 只占用了 16M。這樣比下來(lái)看，還是釋放了不少內(nèi)存?；蛘哒f(shuō)可以見(jiàn)得泄漏的那些 goroutine 占據(jù)了多少內(nèi)存。

在 golang 中創(chuàng)建 goroutine 是一件很容易的事情，但是不合理的使用可能會(huì)導(dǎo)致大量 goroutine 無(wú)法結(jié)束，資源也無(wú)法被釋放，隨著時(shí)間推移造成了內(nèi)存的泄漏。

避免 goroutine 泄漏的關(guān)鍵是要合理管理 goroutine 的生命周期，通過(guò) prometheus/client_golang 導(dǎo)出 runtime 指標(biāo)和利用 net/http/pprof 可以發(fā)現(xiàn)和解決 goroutine 泄漏問(wèn)題。

【本文為51CTO專(zhuān)欄作者“騰訊技術(shù)工程”原創(chuàng)稿件，轉(zhuǎn)載請(qǐng)聯(lián)系原作者(微信號(hào)：Tencent_TEG)】

戳這里，看該作者更多好文