5

20181202-Postmortem-debugging-Go-services-with-Delve[翻译]

 2 years ago
source link: https://cloudsjhan.github.io/2019/01/20/20181202-Postmortem-debugging-Go-services-with-Delve-%E7%BF%BB%E8%AF%91/
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

使用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
#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: https://blog.gopheracademy.com/advent-2018/postmortem-debugging-delve/

作者：Vladimir Varankin
译者：hantmac


report

Recommend

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK