一個 Go 程式系統線程暴漲的問題

這是一個建立於 的文章，其中的資訊可能已經有所發展或是發生改變。最近 fix 了一個 Go 程式系統線程數量暴增的問題，線程數量維持在2，3萬個，有時候甚至更多，這情況明顯不符合 Go 的並發原理。第一次發現線程數巨多是因為這個程式突然 crash 了，由於設定了程式可用的最大線程數，所以線程數一太多就會crash。

這個程式其實就是現在挺火熱的 Swarm，Swarm 這個程式的模式就是作為 client 的角色向數萬個 docker daemon 伺服器建連，維持長串連狀態，然後再定時的從這些 docker daemon 讀取資料。經排查，發現長串連數和線程數基本一致，看到這個現象完全不能夠理解。

最開始的懷疑是 DNS 查詢，走了 cgo 模式，從而導致線程被不斷建立，但不斷翻看代碼能夠肯定的是建連用的 IP，而非網域名稱，最後為了排除 DNS cgo 查詢的影響，我又做了配置強制採用純 Go 方式做 DNS 解析，但並沒有因此線程數就降低。強制使用純 Go DNS 解析器只需要設定如下環境變數即可。

export GODEBUG=netdns=go

然後，繼續在 cgo call 這條路上排查，於是開始定位代碼中是否有採用 cgo 方式調用 C 代碼等，沒發現任何 cgo 調用的可能，最後強制關閉 cgo 也還是無濟於事。

這個時候我也分析過 pprof 資料了，沒有發現任何疑點。pprof 裡本來有一個 threadcreate ，感覺這個工具很用，可不知道為什麼我擷取出來始終只有線程數量，並沒有文檔介紹的棧資訊等。如果你知道使用 pprof/threadcreate 工具的正確姿勢，麻煩告訴我一下，謝謝。

無計可施，試圖用 runtime.Stack() 方法在 goroutine 調度器建立線程的位置列印出調用棧，但由於用來儲存棧的數組會逃逸到堆上，此方法沒能成功，應該是我的姿勢不對吧。最後又簡單的開啟調度器的狀態資訊，可以看到確實建立了很多線程，並且這些線程都不是 idle 狀態，也就說都是在幹活的，極為不能理解，還是無法清楚為什麼會建立這麼多線程。

開啟調度器狀態資訊方法:

export GODEBUG=scheddetail=1,schedtrace=1000

這樣就每一 1000 個毫秒就輸出調度狀態到標準輸出。

經同事提醒用 pstack 看看每個線程都在幹什麼，結果發現絕大多數線程都在 read 系統調用，線程棧如下：

這個時候再 strace 跟蹤此線程出現如下現象：

可以看到這個線程長時間阻塞在 read 調用上了，當然我不敢相信自己的眼睛，還是去進一步求證了 fd 16 確實是網路 connection，網路io 在 Go 的世界裡是不能夠被阻塞的，否則一切都運轉不起來了。這個時候我嚴重懷疑 strace 工具跟蹤的問題，於是到 Go net 庫中添加日誌，確認是否會退出 read 系統調用，重新編譯好 Go 和 swarm，放到線上一跑果然發現 read 系統調用在無資料後並不會返回，也就是阻塞了。再看一個添加日誌後的線程棧：

在 read 系統調用前後添加 start/stop 日誌資訊，可以清楚的看到最後 read 阻塞了。到這個時候，我能夠解釋為什麼線程數暴漲和串連數基本一致了，但 Go 底層 net 庫中確實是為每個 connection 都設定了 nonblock 屬性，可最後又變成了 block。這種情況要麼是核心bug，要麼就是 connection 的屬性最後又被破壞了；我肯定更願意相信後一種可能，突然想起代碼中自訂的 Dial() 方法裡有對 connection 進行 tcp 的選項設定。

// TCP_USER_TIMEOUT is a relatively new feature to detect dead peer from sender side.// Linux supports it since kernel 2.6.37. It's among Golang experimental under// golang.org/x/sys/unix but it doesn't support all Linux platforms yet.// we explicitly define it here until it becomes official in golang.// TODO: replace it with proper package when TCP_USER_TIMEOUT is supported in golang.const tcpUserTimeout = 0x12syscall.SetsockoptInt(int(f.Fd()), syscall.IPPROTO_TCP, tcpUserTimeout, msecs)

將這個 TCP 選項去掉，重新編譯後放到線上一跑，果然一切都對了，線程數也降到正常的幾十個。

TCP_USER_TIMEOUT 選項是在 2.6.37 核心引入，可能是我們用的核心不支援這個選項導致強制設定出現問題，為什麼設定了 TCP_USER_TIMEOUT 就導致 connection 從 nonblock 變成了 block ，值得進一步深究。【 注意：這個結論其實是不完全正確的，更新如下】

真正的原因

這是設定 TCP_USER_TIMEOUT 選項的代碼，之前我將這個函數調用給注釋了，就輕率的認為是設定了這個選項出的問題，最後發現其實真正導致 block 的應該是 conn.File() 調用。底層代碼是這樣的：

// File sets the underlying os.File to blocking mode and returns a copy.// It is the caller's responsibility to close f when finished.// Closing c does not affect f, and closing f does not affect c.//// The returned os.File's file descriptor is different from the connection's.// Attempting to change properties of the original using this duplicate// may or may not have the desired effect.func (c *conn) File() (f *os.File, err error) {f, err = c.fd.dup()if err != nil {err = &OpError{Op: "file", Net: c.fd.net, Source: c.fd.laddr, Addr: c.fd.raddr, Err: err}}return}func (fd *netFD) dup() (f *os.File, err error) {ns, err := dupCloseOnExec(fd.sysfd)if err != nil {return nil, err}// We want blocking mode for the new fd, hence the double negative.// This also puts the old fd into blocking mode, meaning that// I/O will block the thread instead of letting us use the epoll server.// Everything will still work, just with more threads.if err = syscall.SetNonblock(ns, false); err != nil {return nil, os.NewSyscallError("setnonblock", err)}return os.NewFile(uintptr(ns), fd.name()), nil}

不用看代碼，光看看注釋就明白了。所以這裡設定 TCP 選項的姿勢是不對的。

很久以前我在 swarm 的代碼中就發現如下注釋：

// Swarm runnable threads could be large when the number of nodes is large// or under request bursts. Most threads are occupied by network connections.// Increase max thread count from 10k default to 50k to accommodate it.const maxThreadCount int = 50 * 1000debug.SetMaxThreads(maxThreadCount)

好像也發現了線程數巨多的情況，但認為大量串連和並發請求需要消耗這麼多的線程。從這一點看可能沒有深入理解 Go 的並發原理以及 Linux 上的事件驅動。

排查這個問題花了我不少的時間，主要是這個問題的現象和我自己理解的『世界』完全不一致，我很難去想這是 Go 的bug，確實也不是，於是造成很多時候不知道從什麼地方入手，只能讓自己不斷回到 runtime 的代碼中去尋找線程被建立的條件等細節。

之前寫過的一些部落格文章：www.skoo.me