内容简介:Vladimir Varankin 写于 2018/12/02某天,我们生产服务上的几个实例突然不能处理外部进入的流量,HTTP请求成功通过负载均衡到达实例,但是之后却hang住了。接下来记录的是一次调试在线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: blog.gopheracademy.com/advent-2018…
作者:Vladimir Varankin 译者: hantmac
以上就是本文的全部内容,希望本文的内容对大家的学习或者工作能带来一定的帮助,也希望大家多多支持 码农网
猜你喜欢:本站部分资源来源于网络,本站转载出于传递更多信息之目的,版权归原作者或者来源机构所有,如转载稿涉及版权问题,请联系我们。
Hive编程指南
卡普廖洛 (Edward Capriolo)、万普勒 (Dean Wampler)、卢森格林 (Jason Rutherglen) / 曹坤 / 人民邮电出版社 / 2013-12-1 / 69
市场中第一本Hive图书。 Hive在Hadoop系统中的应用趋势比较可观。一起来看看 《Hive编程指南》 这本书的介绍吧!