Postmortem-debugging-Go-services-with-Delve

使用Delve 调试Go服务的一次经历

Vladimir Varankin 写于 2018/12/02

某天，我们生产服务上的几个实例突然不能处理外部进入的流量，HTTP请求成功通过负载均衡到达实例，但是之后却hang住了。接下来记录的是一次调试在线Go服务的惊心动魄的经历。

正是下面逐步演示的操作，帮助我们定位了问题的根本原因。

简单起见，我们将起一个Go写的HTTP服务作为调试使用，这个服务实现的细节暂时不做深究（之后我们将深入分析代码）。一个真实的生产应用可能包含很多组件，这些组件实现了业务罗和服务的基础架构。我们可以确信，这些应用已经在生产环境“身经百战” :)。

源代码以及配置细节可以查看。为了完成接下来的工作，你需要一台Linux系统的虚机，这里我使用插件。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测试工具进行模拟。我的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命令杀掉进程以，但是收不到任何效果。

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 
    
     , ns=-1, val=0) at /usr/local/go/src/runtime/os_linux.go:46#2  0x000000000040c382 in runtime.notesleep (n=0xa9a160 
     
      ) 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调试的技巧，可以继续阅读。

使用Delve调试器

是一个针对Go程序的调试器。它类似于GDB，但是更关注Go的运行时、数据结构以及其他内部的机制。

如果你对Delve的内部实现机制很感兴趣，那么我十分推荐你阅读Alessandro Arzilli在GopherCon EU 2018所作的演讲，[]。

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"模式，并且能够通过与调试器交互。

运行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文件，里面存储大量原始信息。推荐使用命令进一步了解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是一个后端开发工程师，目前就职于. @tvii on Twitter, @narqo on Github

via:

作者：译者：