2. 程式人生 > 其它 >eclipse執行go test_使用 Delve 除錯 Go 服務的一次經歷

eclipse執行go test_使用 Delve 除錯 Go 服務的一次經歷

阿新 • • 發佈：2021-01-04

技術標籤：eclipse執行go test

Vladimir Varankin 寫於 2018/12/02

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

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

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

66730de2bd949ae34e89d5697690878c.png

。

原始碼以及配置細節可以檢視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)
···

 
[email protected]:~$ cd /vagrant/example/server
[email protected]:/vagrant/example/server$ Go build
[email protected]:/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)
···
[email protected]:~$ pgrep server
1628
[email protected]:~$ cd /vagrant
[email protected]:/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.。

(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來分析 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

相關推薦

eclipse執行go test_使用 Delve 除錯 Go 服務的一次經歷

技術標籤：eclipse執行go test Vladimir Varankin 寫於 2018/12/02 某天，我們生產服務上的幾個例項突然不能處理外部進入的流量，HTTP 請求成功通過負載均衡到達例項，但是之後卻 hang 住了。接下來記錄的是一

go筆記-delve除錯工具

讓golang程式生成core檔案 a. ulimit -c unlimited 修改 core 檔案的大小 b. 環境變數export GOTRACEBACK=crash 說明golang程式產生coredump

unittest系統（六）如何在一個測試類多個測試用例執行中只初始化和清理一次？

之前分享了一系列的文章，分別從原理，執行，斷言，執行，測試套件，如何跳過用例來講解unittest，那麼我們繼續分享

使用Go實現優雅重啟服務功能

暴力的重啟服務方案 一般伺服器重啟可以直接通過 kill 命令殺死程序，然後重新啟動一個新的程序即可。但這種方法比較粗暴，有可能導致某些正在處理中的客戶端請求失敗，如果請求正在寫資料，那麼還有可能導致資料丟失

go的WaitGroup併發問題，多次執行結果不相等

技術標籤：go 我有一個50+的併發，使用了WaitGroup，在goroutine中加了個計數器，100次迴圈這個併發，每次得到的計數器並不總等於50。

websocket訊息推送 Go websocket訊息推送服務

https://studygolang.com/p/go-websocket 簡介 golang websocket 服務可通過http介面push訊息到web客戶端，訊息傳送採用golang的併發模式傳送，並非同步記錄傳送的訊息日誌。

Go使用dlv除錯程式碼

用 dlv 除錯 那有同學問了，有沒有其他可以除錯 Go、以及和 Go 程式互動的方法呢？其實是有的！這就是我們要介紹的 dlv 除錯工具，目前它對除錯 Go 程式的支援是最好的。

docker執行容器報錯standard_init_linux.go:211: exec user process caused “exec format error“的可能解決辦法

這個問題主要是由不相容引起的。主要包括幾種不相容： 硬體架構不相容。在 amd 和 arm 架構下構建的映象很有可能不能互通。解決辦法：針對不同的硬體架構構建不同的映象，或者構建跨架構（multi-arch）的映象。

Go——vscode除錯go語言

Mac機下執行命令 更改代理，安裝庫 go envexport GOPROXY=https://goproxy.io,direct go get -v github.com/go-delve/delve/cmd/dlv

53. Socket服務三次握手的示例 | 厚土Go學習筆記

什麼是三次握手呢？這是伺服器和客戶端之間溝通的過程。 首先，客戶端對伺服器傳送了條資訊。

【Go 語言社群】Go worker執行緒池

Worker Pools package main import \"fmt\" import \"time\" // 使用goroutine開啟大小為3的執行緒池

帶你領略Go原始碼的魅力----Go記憶體原理詳解

1、記憶體分割槽 程式碼經過預處理、編譯、彙編、連結4步後生成一個可執行程式。

使用Go env命令設定Go的環境

前言 在進行Go開發的時候，設定Go的環境變數資訊是必須的。下面介紹windows和Linux，以及Go自身提供的命令進行設定的形式

go 學習筆記之go是不是面嚮物件語言是否支援面對物件程式設計?

面向物件程式設計風格深受廣大開發者喜歡,尤其是以 C++,Java 為典型代表的程式語言大行其道,十分流行!

[系列] - 使用 go modules 包管理工具（一）

概述 我想實現一個開箱即用的 API 框架的輪子，這個輪子是基於 Gin 基礎上開發的。

python多執行緒實現程式碼(模擬銀行服務操作流程)

1.模擬銀行服務完成程式程式碼 目前，在以銀行營業大廳為代表的視窗行業中大量使用排隊（叫號）系統，該系統完全模擬了人群排隊全過程，通過取票進隊、排隊等待、叫號服務等功能，代替了人們站隊的辛苦。

PHP FFI呼叫go，居然比go還快

上一篇文章中用PHP的FFI成功了呼叫了cjieba，但是速度實在是慢，4個函式迴圈呼叫20次，用了居然1分50多秒，而且C版本只比PHP快一點點，看來是cjieba本身慢了。

Go語言通過Docker Go語言SDK獲取docker stats的資訊

一、Docker stats介紹 docker stats是docker提供的一個監控工具，非常的好用，之前一篇部落格中簡單介紹來了一下，可以先去簡單看看docker stats 介紹

ASP.NET Core 設定執行埠，啟動多個服務例項

想要通過命令列方式執行ASP.NET Core，指定執行的埠號，該怎麼做呢？ 兩種方法：

go 學習筆記基礎篇（一）

golang 變數宣告 var 宣告單個變數 var 變數名稱 型別 變數名稱命名： a. 字母、數字、下劃線組成，首字母不能為數字