【翻譯】Postmortem-debugging-Go-services-with-Delve

hantmac發表於2019-01-20
Go

Postmortem-debugging-Go-services-with-Delve

使用Delve 除錯Go服務的一次經歷

Vladimir Varankin 寫於 2018/12/02

某天，我們生產服務上的幾個例項突然不能處理外部進入的流量，HTTP請求成功通過負載均衡到達例項，但是之後卻hang住了。接下來記錄的是一次除錯線上Go服務的驚心動魄的經歷。

正是下面逐步演示的操作，幫助我們定位了問題的根本原因。

簡單起見，我們將起一個Go寫的HTTP服務作為除錯使用，這個服務實現的細節暫時不做深究（之後我們將深入分析程式碼）。一個真實的生產應用可能包含很多元件，這些元件實現了業務羅和服務的基礎架構。我們可以確信，這些應用已經在生產環境“身經百戰” :)。

原始碼以及配置細節可以檢視GitHub倉庫。為了完成接下來的工作，你需要一臺Linux系統的虛機，這裡我使用vagrant-hostmanager外掛。Vagrantfile在GitHub倉庫的根目錄，可以檢視更多細節。

讓我們開啟虛機，構建HTTP服務並且執行起來，可以看到下面的輸出：

$ vagrant upBringing machine 'server-test-1' up with 'virtualbox' provider...$ vagrant ssh server-test-1Welcome to Ubuntu 18.04.1 LTS (GNU/Linux 4.15.0-33-generic x86_64)···vagrant@server-test-1:~$ cd /vagrant/example/servervagrant@server-test-1:/vagrant/example/server$ go buildvagrant@server-test-1:/vagrant/example/server$ ./server --addr=:10080server 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-1Welcome to Ubuntu 18.04.1 LTS (GNU/Linux 4.15.0-33-generic x86_64)···vagrant@server-test-1:~$ pgrep server1628vagrant@server-test-1:~$ cd /vagrantvagrant@server-test-1:/vagrant$ sudo gdb --pid=1628 example/server/serverGNU gdb (Ubuntu 8.1-0ubuntu3) 8.1.0.20180409-git···複製程式碼

偵錯程式連線到伺服器程式之後，我們可以執行GDB的bt命令（aka backtrace）來檢查當前執行緒的堆疊資訊：

(gdb) bt#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:532#1  0x000000000042b08b in runtime.futexsleep (addr=0xa9a160 <
runtime.m0+320>
, ns=-1, val=0) at /usr/local/go/src/runtime/os_linux.go:46#2  0x000000000040c382 in runtime.notesleep (n=0xa9a160 <
runtime.m0+320>
) at /usr/local/go/src/runtime/lock_futex.go:151#3  0x0000000000433b4a in runtime.stoplockedm () at /usr/local/go/src/runtime/proc.go:2165#4  0x0000000000435279 in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2565#5  0x00000000004353fe in runtime.park_m (gp=0xc000066d80) at /usr/local/go/src/runtime/proc.go:2676#6  0x000000000045ae1b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:299#7  0x000000000045ad39 in runtime.rt0_go () at /usr/local/go/src/runtime/asm_amd64.s:201#8  0x0000000000000000 in ?? ()複製程式碼

說實話我並不是GDB的專家，但是顯而易見Go執行時似乎使執行緒進入睡眠狀態了，為什麼呢？

除錯一個正在執行的程式是不明智的，不如將該執行緒的coredump儲存下來，進行離線分析。我們可以使用GDB的gcore命令，該命令將core檔案儲存在當前工作目錄並命名為core.<
process_id>
。

(gdb) gcoreSaved corefile core.1628(gdb) quitA debugging session is active. Inferior 1 [process 1628] will be detached.Quit anyway? (y or n) yDetaching 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 --logAPI server listening at: [::]:44441INFO[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 inChannelfunc (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 20Switched from 0 to 20 (thread 1628)(dlv) stack -full0  0x000000000042d7bb in runtime.gopark   at /usr/local/go/src/runtime/proc.go:303       lock = unsafe.Pointer(0xc000104058)       reason = waitReasonChanSend···3  0x00000000004066a5 in runtime.chansend1   at /usr/local/go/src/runtime/chan.go:125       c = (unreadable empty OP stack)       elem = (unreadable empty OP stack)4  0x000000000062478f 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)5  0x0000000000624e64 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)6  0x0000000000624a2f 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

via: blog.gopheracademy.com/advent-2018…

作者：Vladimir Varankin譯者：hantmac

來源：https://juejin.im/post/5c449874f265da61715e9be8

相關文章