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

時間 2019-11-26

標籤翻譯 postmortem debugging services delve 简体版

原文原文鏈接

Postmortem-debugging-Go-services-with-Delve

使用Delve 調試Go服務的一次經歷

Vladimir Varankin 寫於 2018/12/02linux

某天，咱們生產服務上的幾個實例忽然不能處理外部進入的流量，HTTP請求成功經過負載均衡到達實例，可是以後卻hang住了。接下來記錄的是一次調試在線Go服務的驚心動魄的經歷。git

正是下面逐步演示的操做，幫助咱們定位了問題的根本緣由。github

簡單起見，咱們將起一個Go寫的HTTP服務做爲調試使用，這個服務實現的細節暫時不作深究（以後咱們將深刻分析代碼）。一個真實的生產應用可能包含不少組件，這些組件實現了業務羅和服務的基礎架構。咱們能夠確信，這些應用已經在生產環境「身經百戰」 :)。golang

源代碼以及配置細節能夠查看GitHub倉庫。爲了完成接下來的工做，你須要一臺Linux系統的虛機，這裏我使用vagrant-hostmanager插件。Vagrantfile在GitHub倉庫的根目錄，能夠查看更多細節。shell

讓咱們開啓虛機，構建HTTP服務而且運行起來，能夠看到下面的輸出：json

$ 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並執行下面的命令：ubuntu

$ 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跑完以後，服務器已經不能處理任何請求：api

$ curl --max-time 5 'http://server-test-1:10080/'
curl: (28) Operation timed out after 5001 milliseconds with 0 bytes received
複製代碼

咱們遇到麻煩了！讓咱們分析一下。bash

在咱們生產服務的真實場景中，服務器起來之後，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
#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) 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
0  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