使用 Delve 除錯 Go 服務的一次經歷
Vladimir Varankin 寫於 2018/12/02
某天，我們生產服務上的幾個例項突然不能處理外部進入的流量，HTTP 請求成功通過負載均衡到達例項，但是之後卻 hang 住了。接下來記錄的是一次除錯線上 Go 服務的驚心動魄的經歷。
正是下面逐步演示的操作，幫助我們定位了問題的根本原因。
簡單起見，我們將起一個 Go 寫的 HTTP 服務作為除錯使用，這個服務實現的細節暫時不做深究（之後我們將深入分析程式碼）。一個真實的生產應用可能包含很多元件，這些元件實現了業務羅和服務的基礎架構。我們可以確信，這些應用已經在生產環境“身經百戰” :)。
原始碼以及配置細節可以檢視GitHub 倉庫
。為了完成接下來的工作，你需要一臺 Linux 系統的虛機，這裡我使用vagrant-hostmanager
外掛。Vagrantfile
在 GitHub 倉庫的根目錄，可以檢視更多細節。
讓我們開啟虛機，構建 HTTP 服務並且執行起來，可以看到下面的輸出：
$ Vagrant up Bringing Machine 'server-test-1' up with 'virtualbox' provider... $ Vagrant SSH server-test-1 Welcome to Ubuntu 18.04.1 LTS (GNU/Linux 4.15.0-33-generic x86_64) ··· vagrant@server-test-1:~$ cd /vagrant/example/server vagrant@server-test-1:/vagrant/example/server$ Go build vagrant@server-test-1:/vagrant/example/server$ ./server --addr=:10080 server listening addr=:10080
通過curl
傳送請求到所起的 HTTP 服務，可以判斷其是否處於工作狀態，新開一個 terminal 並執行下面的命令：
$ curl 'http://server-test-1:10080' OK
為了模擬失敗的情況，我們需要傳送大量請求到 HTTP 服務，這裡我們使用 HTTP benchmark 測試工具wrk 進行模擬。我的 MacBook 是 4 核的，所以使用 4 個執行緒執行 wrk，能夠產生 1000 個連線，基本能夠滿足需求。
$ wrk -d1m -t4 -c1000 'http://server-test-1:10080' Running 1m test @ http://server-test-1:10080 4 threads and 1000 connections ···
一會的時間，伺服器 hang 住了。甚至等 wrk 跑完之後，伺服器已經不能處理任何請求：
$ curl --max-time 5 'http://server-test-1:10080/' curl: (28) Operation timed out after 5001 milliseconds with 0 bytes received
我們遇到麻煩了！讓我們分析一下。
在我們生產服務的真實場景中，伺服器起來以後，goroutines 的數量由於請求的增多而迅速增加，之後便失去響應。對 pprof 除錯控制代碼的請求變得非常非常慢，看起來就像伺服器“死掉了”。同樣，我們也嘗試使用SIGQUIT
命令殺掉程序以釋放所執行 Goroutines 堆疊
，但是收不到任何效果。
GDB 和 Coredump
我們可以使用 GDB（GNU Debugger）嘗試進入正在執行的服務內部。
在生產環境執行偵錯程式可能需要額外的許可權，所以與你的團隊提前溝通是很明智的。
在虛機上再開啟一個 SSH 會話，找到伺服器的程序 id 並使用偵錯程式連線到該程序：
$ Vagrant SSH server-test-1 Welcome to Ubuntu 18.04.1 LTS (GNU/Linux 4.15.0-33-generic x86_64) ··· vagrant@server-test-1:~$ pgrep server 1628 vagrant@server-test-1:~$ cd /vagrant vagrant@server-test-1:/vagrant$ sudo gdb --pid=1628 example/server/server GNU gdb (Ubuntu 8.1-0ubuntu3) 8.1.0.20180409-git ···
偵錯程式連線到伺服器程序之後，我們可以執行 GDB 的bt
命令（aka backtrace）來檢查當前執行緒的堆疊資訊：
(gdb) bt #0runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:532 #10x000000000042b08b in runtime.futexsleep (addr=0xa9a160 <runtime.m0+320>, ns=-1, val=0) at /usr/local/go/src/runtime/os_linux.go:46 #20x000000000040c382 in runtime.notesleep (n=0xa9a160 <runtime.m0+320>) at /usr/local/go/src/runtime/lock_futex.go:151 #30x0000000000433b4a in runtime.stoplockedm () at /usr/local/go/src/runtime/proc.go:2165 #40x0000000000435279 in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2565 #50x00000000004353fe in runtime.park_m (gp=0xc000066d80) at /usr/local/go/src/runtime/proc.go:2676 #60x000000000045ae1b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:299 #70x000000000045ad39 in runtime.rt0_go () at /usr/local/go/src/runtime/asm_amd64.s:201 #80x0000000000000000 in ?? ()
說實話我並不是 GDB 的專家，但是顯而易見 Go 執行時似乎使執行緒進入睡眠狀態了，為什麼呢？
除錯一個正在執行的程序是不明智的，不如將該執行緒的 coredump 儲存下來，進行離線分析。我們可以使用 GDB 的gcore
命令，該命令將 core 檔案儲存在當前工作目錄並命名為core.<process_id>
。
(gdb) gcore Saved corefile core.1628 (gdb) quit A debugging session is active. Inferior 1 [process 1628] will be detached. Quit anyway? (y or n) y Detaching from program: /vagrant/example/server/server, process 1628
core 檔案儲存後，伺服器沒必要繼續執行，使用kill -9
結束它。
我們能夠注意到，即使是一個簡單的伺服器，core 檔案依然會很大（我這一份是 1.2G）, 對於生產的服務來說，可能會更加巨大。
如果需要了解更多使用 GDB 除錯的技巧，可以繼續閱讀使用 GDB 除錯 Go 程式碼 。
使用 Delve 偵錯程式
Delve 是一個針對 Go 程式的偵錯程式。它類似於 GDB，但是更關注 Go 的執行時、資料結構以及其他內部的機制。
如果你對 Delve 的內部實現機制很感興趣，那麼我十分推薦你閱讀 Alessandro Arzilli 在 GopherCon EU 2018 所作的演講，[Internal Architecture of Delve, a Debugger For Go ]。
Delve 是用 Go 寫的，所以安裝起來非常簡單：
$ Go get -u Github.com/derekparker/delve/cmd/dlv
Delve 安裝以後，我們就可以通過執行dlv core <path to service binary> <core file>
來分析 core 檔案。我們先列出執行 coredump 時正在執行的所有 Goroutines。Delve 的goroutines
命令如下：
$ dlv core example/server/server core.1628 (dlv) Goroutines ··· Goroutine 4611 - User: /vagrant/example/server/metrics.go:113 main.(*Metrics).CountS (0x703948) Goroutine 4612 - User: /vagrant/example/server/metrics.go:113 main.(*Metrics).CountS (0x703948) Goroutine 4613 - User: /vagrant/example/server/metrics.go:113 main.(*Metrics).CountS (0x703948)
不幸的是，在真實生產環境下，這個列表可能會很長，甚至會超出 terminal 的緩衝區。由於伺服器為每一個請求都生成一個對應的 Goroutine，所以goroutines
命令生成的列表可能會有百萬條。我們假設現在已經遇到這個問題，並想一個方法來解決它。
Delve 支援 "headless" 模式，並且能夠通過JSON-RPC API 與偵錯程式互動。
執行dlv core
命令，指定想要啟動的 Delve API server：
$ dlv core example/server/server core.1628 --listen :44441 --headless --log API server listening at: [::]:44441 INFO[0000] opening core file core.1628 (executable example/server/server)layer=debugger
除錯伺服器執行後，我們可以傳送命令到其 TCP 埠並將返回結果以原生 JSON 的格式儲存。我們以上面相同的方式得到正在執行的 Goroutines，不同的是我們將結果儲存到檔案中：
$ Echo -n '{"method":"RPCServer.ListGoroutines","params":[],"id":2}' | nc -w 1 localhost 44441 > server-test-1_dlv-rpc-list_goroutines.json
現在我們擁有了一個（比較大的）JSON 檔案，裡面儲存大量原始資訊。推薦使用jq 命令進一步瞭解 JSON 資料的原貌，舉例：這裡我獲取 JSON 資料的 result 欄位的前三個物件：
$ jq '.result[0:3]' server-test-1_dlv-rpc-list_goroutines.json
[
{
"id": 1,
"currentLoc": {
"pc": 4380603,
"file": "/usr/local/go/src/runtime/proc.go",
"line": 303,
"function": {
"name": "runtime.gopark",
"value": 4380368,
"type": 0,
"goType": 0,
"optimized": true
}
},
"userCurrentLoc": {
"pc": 6438159,
"file": "/vagrant/example/server/main.go",
"line": 52,
"function": {
"name": "main.run",
"value": 6437408,
"type": 0,
"goType": 0,
"optimized": true
}
},
"goStatementLoc": {
"pc": 4547433,
"file": "/usr/local/go/src/runtime/asm_amd64.s",
"line": 201,
"function": {
"name": "runtime.rt0_go",
"value": 4547136,
"type": 0,
"goType": 0,
"optimized": true
}
},
"startLoc": {
"pc": 4379072,
"file": "/usr/local/go/src/runtime/proc.go",
"line": 110,
"function": {
"name": "runtime.main",
"value": 4379072,
"type": 0,
"goType": 0,
"optimized": true
}
},
"threadID": 0,
"unreadable": ""
},
···
]
JSON 資料中的每個物件都代表了一個 Goroutine。通過命令手冊
可知，goroutines
命令可以獲得每一個 Goroutines 的資訊。通過手冊我們能夠分析出userCurrentLoc
欄位是伺服器原始碼中 Goroutines 最後出現的地方。
為了能夠了解當 core file 建立的時候，goroutines 正在做什麼，我們需要收集 JSON 檔案中包含userCurrentLoc
欄位的函式名字以及其行號：
$ jq -c '.result[] | [.userCurrentLoc.function.name, .userCurrentLoc.line]' server-test-1_dlv-rpc-list_goroutines.json | sort | uniq -c 1 ["internal/poll.runtime_pollWait",173] 1000 ["main.(*Metrics).CountS",95] 1 ["main.(*Metrics).SetM",105] 1 ["main.(*Metrics).startOutChannelConsumer",179] 1 ["main.run",52] 1 ["os/signal.signal_recv",139] 6 ["runtime.gopark",303]
大量的 Goroutines( 上面是 1000 個 ) 在函式main.(*Metrics).CoutS
的 95 行被阻塞。現在我們回頭看一下我們伺服器的原始碼
。
在main
包中找到Metrics
結構體並且找到它的CountS
方法（example/server/metrics.go）。
// CountS increments counter per second.
func (m *Metrics) CountS(key string) {
m.inChannel <- NewCountMetric(key, 1, second)
}
我們的伺服器在往inChannel
通道傳送的時候阻塞住了。讓我們找出誰負責從這個通道讀取資料，深入研究程式碼之後我們找到了下面的函式
：
// starts a consumer for inChannel
func (m *Metrics) startInChannelConsumer() {
for inMetrics := range m.inChannel {
// ···
}
}
這個函式逐個地從通道中讀取資料並加以處理，那麼什麼情況下發送到這個通道的任務會被阻塞呢？
當處理通道的時候，根據 Dave Cheney 的通道準則 ，只有四種情況可能導致通道有問題：
- 向一個 nil 通道傳送
- 從一個 nil 通道接收
- 向一個已關閉的通道傳送
- 從一個已關閉的通道接收並立即返回零值
第一眼就看到了“向一個 nil 通道傳送”，這看起來像是問題的原因。但是反覆檢查程式碼後，inChannel
是由Metrics
初始化的，不可能為 nil。
n 你可能會注意到，使用jq
命令獲取到的資訊中，沒有startInChannelConsumer
方法。會不會是因為在main.(*Metrics).startInChannelConsumer
的某個地方阻塞而導致這個（可緩衝）通道滿了？
Delve 能夠提供從開始位置到userCurrentLoc
欄位之間的初始位置資訊，這個資訊儲存到startLoc
欄位中。使用下面的 jq 命令可以查詢出所有 Goroutines, 其初始位置都在函式startInChannelConsumer
中：
$ jq '.result[] | select(.startLoc.function.name | test("startInChannelConsumer$"))' server-test-1_dlv-rpc-list_goroutines.json
{
"id": 20,
"currentLoc": {
"pc": 4380603,
"file": "/usr/local/go/src/runtime/proc.go",
"line": 303,
"function": {
"name": "runtime.gopark",
"value": 4380368,
"type": 0,
"goType": 0,
"optimized": true
}
},
"userCurrentLoc": {
"pc": 6440847,
"file": "/vagrant/example/server/metrics.go",
"line": 105,
"function": {
"name": "main.(*Metrics).SetM",
"value": 6440672,
"type": 0,
"goType": 0,
"optimized": true
}
},
"startLoc": {
"pc": 6440880,
"file": "/vagrant/example/server/metrics.go",
"line": 109,
"function": {
"name": "main.(*Metrics).startInChannelConsumer",
"value": 6440880,
"type": 0,
"goType": 0,
"optimized": true
}
},
···
}
結果中有一條資訊非常振奮人心！
在main.(*Metrics).startInChannelConsumer
，109 行（看結果中的 startLoc 欄位），有一個 id 為 20 的 Goroutines 阻塞住了！
拿到 Goroutines 的 id 能夠大大降低我們搜尋的範圍（並且我們再也不用深入龐大的 JSON 檔案了）。使用 Delve 的goroutines
命令我們能夠將當前 Goroutines 切換到目標 Goroutines，然後可以使用stack
命令列印該 Goroutines 的堆疊資訊：
$ dlv core example/server/server core.1628
(dlv) Goroutine 20
Switched from 0 to 20 (thread 1628)
(dlv) stack -full
00x000000000042d7bb in runtime.gopark
at /usr/local/go/src/runtime/proc.go:303
lock = unsafe.Pointer(0xc000104058)
reason = waitReasonChanSend
···
30x00000000004066a5 in runtime.chansend1
at /usr/local/go/src/runtime/chan.go:125
c = (unreadable empty OP stack)
elem = (unreadable empty OP stack)
40x000000000062478f in main.(*Metrics).SetM
at /vagrant/example/server/metrics.go:105
key = (unreadable empty OP stack)
m = (unreadable empty OP stack)
value = (unreadable empty OP stack)
50x0000000000624e64 in main.(*Metrics).sendMetricsToOutChannel
at /vagrant/example/server/metrics.go:146
m = (*main.Metrics)(0xc000056040)
scope = 0
updateInterval = (unreadable could not find loclist entry at 0x89f76 for address 0x624e63)
60x0000000000624a2f in main.(*Metrics).startInChannelConsumer
at /vagrant/example/server/metrics.go:127
m = (*main.Metrics)(0xc000056040)
inMetrics = main.Metric {Type: TypeCount, Scope: 0, Key: "server.req-incoming",...+2 more}
nextUpdate = (unreadable could not find loclist entry at 0x89e86 for address 0x624a2e)
從下往上分析：
（6）一個來自通道的新inMetrics
值在main.(*Metrics).startInChannelConsumer
中被接收
（5）我們呼叫main.(*Metrics).sendMetricsToOutChannel
並且在example/server/metrics.go
的 146 行進行處理
（4）然後main.(*Metrics).SetM
被呼叫
一直執行到runtime.gopark
中的waitReasonChanSend
阻塞！
一切的一切都明朗了！
單個 Goroutines 中，一個從緩衝通道讀取資料的函式，同時也在往通道中傳送資料。當進入通道的值達到通道的容量時，消費函式繼續往已滿的通道中傳送資料就會造成自身的死鎖。由於單個通道的消費者死鎖，那麼每一個嘗試往通道中傳送資料的請求都會被阻塞。
這就是我們的故事，使用上述除錯技術幫助我們發現了問題的根源。那些程式碼是很多年前寫的，甚至從沒有人看過這些程式碼，也萬萬沒有想到會導致這麼大的問題。
如你所見，並不是所有問題都能由工具解決，但是工具能夠幫助你更好地工作。我希望，通過此文能夠激勵你多多嘗試這些工具。我非常樂意傾聽你們處理類似問題的其它解決方案。
Vladimir是一個後端開發工程師，目前就職於 adjust.com. @tvii on Twitter, @narqo on Github