调试利器：dump goroutine 的 stacktrace

标签： Go | 发表时间：2016-12-21 13:33 | 作者：
出处：http://colobu.com/

Stack trace是指堆栈回溯信息，在当前时间，以当前方法的执行点开始，回溯调用它的方法的方法的执行点，然后继续回溯，这样就可以跟踪整个方法的调用,大家比较熟悉的是JDK所带的 jstack工具，可以把Java的所有线程的stack trace都打印出来。

它有什么用呢？用处非常的大，当应用出现一些状况的时候，比如某个模块不执行， 锁竞争、CPU占用非常高等问题， 又没有足够的log信息可以分析，那么可以查看stack trace信息，看看线程都被阻塞或者运行在那些代码上，然后定位问题所在。

对于Go开发的程序，有没有类似 jstack这样的利器呢，目前我还没有看到，但是我们可以通过其它途径也很方便的输出goroutine的stack trace信息。

本文介绍了几种方法，尤其是最后介绍的方法比较有用。

异常退出情况下输出stacktrace

通过panic

如果应用中有没recover的panic,或者应用在运行的时候出现运行时的异常，那么程序自动会将当前的goroutine的stack trace打印出来。

比如下面的程序，如果你运行会抛出一个panic。

     
1
     
2
     
3
     
4
     
5
     
6
     
7
     
8
     
9
     
10
     
11
     
12
     
13
     
14
     
15
     
16
     
17
     
18
     
19
     
20
     
21
     
22
     
23
     
24
     
25
     
26
 
     
package main
     
     
import (
     
	"time"
     
)
     
     
func main() {
     
	go a()
     
	m1()
     
}
     
     
func m1() {
     
	m2()
     
}
     
     
func m2() {
     
	m3()
     
}
     
     
func m3() {
     
	panic("panic from m3")
     
}
     
     
func a() {
     
	time.Sleep(time.Hour)
     
}

输出下面的stack trace:

     
1
     
2
     
3
     
4
     
5
     
6
     
7
     
8
     
9
     
10
     
11
     
12
     
13
     
14
     
15
 
     
dump go run p.go
     
panic: panic from m3
     
     
goroutine 1 [running]:
     
panic(0x596a0, 0xc42000a1a0)
     
	/usr/local/Cellar/go/1.7.4/libexec/src/runtime/panic.go:500 +0x1a1
     
main.m3()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/p.go:21 +0x6d
     
main.m2()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/p.go:17 +0x14
     
main.m1()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/p.go:13 +0x14
     
main.main()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/p.go:9 +0x3a
     
exit status 2

从这个信息中我们可以看到p.go的第9行是main方法，它在这一行调用m1方法，m1方法在第13行调用m2方法，m2方法在第17行调用m3方法，m3方法在第21出现panic， 它们运行在goroutine 1中，当前goroutine 1的状态是running状态。

如果想让它把所有的goroutine信息都输出出来，可以设置 GOTRACEBACK=1:

     
1
     
2
     
3
     
4
     
5
     
6
     
7
     
8
     
9
     
10
     
11
     
12
     
13
     
14
     
15
     
16
     
17
     
18
     
19
     
20
     
21
     
22
     
23
 
     
GOTRACEBACK=1 go run p.go
     
panic: panic from m3
     
     
goroutine 1 [running]:
     
panic(0x596a0, 0xc42000a1b0)
     
	/usr/local/Cellar/go/1.7.4/libexec/src/runtime/panic.go:500 +0x1a1
     
main.m3()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/p.go:21 +0x6d
     
main.m2()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/p.go:17 +0x14
     
main.m1()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/p.go:13 +0x14
     
main.main()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/p.go:9 +0x3a
     
     
goroutine 4 [sleep]:
     
time.Sleep(0x34630b8a000)
     
	/usr/local/Cellar/go/1.7.4/libexec/src/runtime/time.go:59 +0xe1
     
main.a()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/p.go:25 +0x30
     
created by main.main
     
	/Users/yuepan/go/src/github.com/smallnest/dump/p.go:8 +0x35
     
exit status 2

同样你也可以分析这个stack trace的信息，得到方法调用点的情况，同时这个信息将两个goroutine的stack trace都打印出来了，而且goroutine 4的状态是sleep状态。

Go官方文档对这个环境变量有 介绍：

The GOTRACEBACK variable controls the amount of output generated when a Go program fails due to an unrecovered panic or an unexpected runtime condition. By default, a failure prints a stack trace for the current goroutine, eliding functions internal to the run-time system, and then exits with exit code 2. The failure prints stack traces for all goroutines if there is no current goroutine or the failure is internal to the run-time. GOTRACEBACK=none omits the goroutine stack traces entirely. GOTRACEBACK=single (the default) behaves as described above. GOTRACEBACK=all adds stack traces for all user-created goroutines. GOTRACEBACK=system is like “all” but adds stack frames for run-time functions and shows goroutines created internally by the run-time. GOTRACEBACK=crash is like “system” but crashes in an operating system-specific manner instead of exiting. For example, on Unix systems, the crash raises SIGABRT to trigger a core dump. For historical reasons, the GOTRACEBACK settings 0, 1, and 2 are synonyms for none, all, and system, respectively. The runtime/debug package's SetTraceback function allows increasing the amount of output at run time, but it cannot reduce the amount below that specified by the environment variable. See https://golang.org/pkg/runtime/debug/#SetTraceback.

你可以设置 none、 all、 system、 single、 crash，历史原因， 你可以可是设置数字 0、 1、 2，分别代表 none、 all、 system。

通过SIGQUIT信号

如果程序没有发生panic,但是程序有问题，"假死“不工作，我们想看看哪儿出现了问题，可以给程序发送 SIGQUIT信号，也可以输出stack trace信息。
比如下面的程序:

     
1
     
2
     
3
     
4
     
5
     
6
     
7
     
8
     
9
     
10
     
11
     
12
     
13
     
14
     
15
     
16
     
17
     
18
     
19
     
20
     
21
     
22
     
23
     
24
     
25
     
26
 
     
package main
     
     
import (
     
	"time"
     
)
     
     
func main() {
     
	go a()
     
	m1()
     
}
     
     
func m1() {
     
	m2()
     
}
     
     
func m2() {
     
	m3()
     
}
     
     
func m3() {
     
	time.Sleep(time.Hour)
     
}
     
     
func a() {
     
	time.Sleep(time.Hour)
     
}

你可以运行 kill -SIGQUIT <pid> 杀死这个程序，程序在退出的时候输出strack trace。

正常情况下输出stacktrace

上面的情况是必须要求程序退出才能打印出stack trace信息，但是有时候我们只是需要跟踪分析一下程序的问题，而不希望程序中断运行。所以我们需要其它的方法来执行。

你可以暴漏一个命令、一个API或者监听一个信号，然后调用相应的方法把stack trace打印出来。

打印出当前goroutine的 stacktrace

通过 debug.PrintStack()方法可以将当前所在的goroutine的stack trace打印出来，如下面的程序。

     
1
     
2
     
3
     
4
     
5
     
6
     
7
     
8
     
9
     
10
     
11
     
12
     
13
     
14
     
15
     
16
     
17
     
18
     
19
     
20
     
21
     
22
     
23
     
24
     
25
     
26
     
27
     
28
 
     
package main
     
     
import (
     
	"runtime/debug"
     
	"time"
     
)
     
     
func main() {
     
	go a()
     
	m1()
     
}
     
     
func m1() {
     
	m2()
     
}
     
     
func m2() {
     
	m3()
     
}
     
     
func m3() {
     
	debug.PrintStack()
     
	time.Sleep(time.Hour)
     
}
     
     
func a() {
     
	time.Sleep(time.Hour)
     
}

打印出所有goroutine的 stacktrace

可以通过 pprof.Lookup("goroutine").WriteTo将所有的goroutine的stack trace都打印出来，如下面的程序：

     
1
     
2
     
3
     
4
     
5
     
6
     
7
     
8
     
9
     
10
     
11
     
12
     
13
     
14
     
15
     
16
     
17
     
18
     
19
     
20
     
21
     
22
     
23
     
24
     
25
     
26
     
27
     
28
     
29
 
     
package main
     
     
import (
     
	"os"
     
	"runtime/pprof"
     
	"time"
     
)
     
     
func main() {
     
	go a()
     
	m1()
     
}
     
     
func m1() {
     
	m2()
     
}
     
     
func m2() {
     
	m3()
     
}
     
     
func m3() {
     
	pprof.Lookup("goroutine").WriteTo(os.Stdout, 1)
     
	time.Sleep(time.Hour)
     
}
     
     
func a() {
     
	time.Sleep(time.Hour)
     
}

较完美的输出 stacktrace

你可以使用 runtime.Stack得到所有的goroutine的stack trace信息，事实上前面 debug.PrintStack()也是通过这个方法获得的。

为了更方便的随时的得到应用所有的goroutine的stack trace信息，我们可以监听 SIGUSER1信号，当收到这个信号的时候就将stack trace打印出来。发送信号也很简单，通过 kill -SIGUSER1 <pid>就可以，不必担心 kill会将程序杀死，它只是发了一个信号而已。

     
1
     
2
     
3
     
4
     
5
     
6
     
7
     
8
     
9
     
10
     
11
     
12
     
13
     
14
     
15
     
16
     
17
     
18
     
19
     
20
     
21
     
22
     
23
     
24
     
25
     
26
     
27
     
28
     
29
     
30
     
31
     
32
     
33
     
34
     
35
     
36
     
37
     
38
     
39
     
40
     
41
     
42
     
43
     
44
     
45
     
46
     
47
     
48
     
49
 
     
package main
     
     
import (
     
	"fmt"
     
	"os"
     
	"os/signal"
     
	"runtime"
     
	"syscall"
     
	"time"
     
)
     
     
func main() {
     
	setupSigusr1Trap()
     
     
	go a()
     
	m1()
     
}
     
     
func m1() {
     
	m2()
     
}
     
     
func m2() {
     
	m3()
     
}
     
     
func m3() {
     
	time.Sleep(time.Hour)
     
}
     
     
func a() {
     
	time.Sleep(time.Hour)
     
}
     
     
func setupSigusr1Trap() {
     
	c := make(chan os.Signal, 1)
     
	signal.Notify(c, syscall.SIGUSR1)
     
	go func() {
     
		for range c {
     
			DumpStacks()
     
		}
     
	}()
     
}
     
     
func DumpStacks() {
     
	buf := make([]byte, 16384)
     
	buf = buf[:runtime.Stack(buf, true)]
     
	fmt.Printf("=== BEGIN goroutine stack dump ===\n%s\n=== END goroutine stack dump ===", buf)
     
}

输出结果很直观，方便检查。

     
1
     
2
     
3
     
4
     
5
     
6
     
7
     
8
     
9
     
10
     
11
     
12
     
13
     
14
     
15
     
16
     
17
     
18
     
19
     
20
     
21
     
22
     
23
     
24
     
25
     
26
     
27
     
28
     
29
     
30
     
31
     
32
     
33
     
34
     
35
     
36
     
37
     
38
     
39
     
40
     
41
     
42
     
43
     
44
     
45
     
46
     
47
     
48
     
49
     
50
 
     
=== BEGIN goroutine stack dump ===
     
goroutine 36 [running]:
     
main.DumpStacks()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/d3.go:47 +0x77
     
main.setupSigusr1Trap.func1(0xc420070060)
     
	/Users/yuepan/go/src/github.com/smallnest/dump/d3.go:40 +0x73
     
created by main.setupSigusr1Trap
     
	/Users/yuepan/go/src/github.com/smallnest/dump/d3.go:42 +0xec
     
     
goroutine 1 [sleep]:
     
time.Sleep(0x34630b8a000)
     
	/usr/local/Cellar/go/1.7.4/libexec/src/runtime/time.go:59 +0xe1
     
main.m3()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/d3.go:28 +0x30
     
main.m2()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/d3.go:24 +0x14
     
main.m1()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/d3.go:20 +0x14
     
main.main()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/d3.go:16 +0x3f
     
     
goroutine 34 [syscall]:
     
os/signal.signal_recv(0xff280)
     
	/usr/local/Cellar/go/1.7.4/libexec/src/runtime/sigqueue.go:116 +0x157
     
os/signal.loop()
     
	/usr/local/Cellar/go/1.7.4/libexec/src/os/signal/signal_unix.go:22 +0x22
     
created by os/signal.init.1
     
	/usr/local/Cellar/go/1.7.4/libexec/src/os/signal/signal_unix.go:28 +0x41
     
     
goroutine 35 [select, locked to thread]:
     
runtime.gopark(0xb5cc8, 0x0, 0xab3ef, 0x6, 0x18, 0x2)
     
	/usr/local/Cellar/go/1.7.4/libexec/src/runtime/proc.go:259 +0x13a
     
runtime.selectgoImpl(0xc42008d730, 0x0, 0x18)
     
	/usr/local/Cellar/go/1.7.4/libexec/src/runtime/select.go:423 +0x11d9
     
runtime.selectgo(0xc42008d730)
     
	/usr/local/Cellar/go/1.7.4/libexec/src/runtime/select.go:238 +0x1c
     
runtime.ensureSigM.func1()
     
	/usr/local/Cellar/go/1.7.4/libexec/src/runtime/signal1_unix.go:304 +0x2d1
     
runtime.goexit()
     
	/usr/local/Cellar/go/1.7.4/libexec/src/runtime/asm_amd64.s:2086 +0x1
     
     
goroutine 37 [sleep]:
     
time.Sleep(0x34630b8a000)
     
	/usr/local/Cellar/go/1.7.4/libexec/src/runtime/time.go:59 +0xe1
     
main.a()
     
	/Users/yuepan/go/src/github.com/smallnest/dump/d3.go:32 +0x30
     
created by main.main
     
	/Users/yuepan/go/src/github.com/smallnest/dump/d3.go:15 +0x3a
     
     
=== END goroutine stack dump ===

当然，这段代码也不是我原创的，这是docker代码库中的一段 代码，很简单，也很强大。

参考文档

  1. http://stackoverflow.com/questions/19094099/how-to-dump-goroutine-stacktraces
  2. https://golang.org/pkg/runtime/

相关 [调试 dump goroutine] 推荐：

调试利器：dump goroutine 的 stacktrace

- - 鸟窝
Stack trace是指堆栈回溯信息，在当前时间，以当前方法的执行点开始，回溯调用它的方法的方法的执行点，然后继续回溯，这样就可以跟踪整个方法的调用,大家比较熟悉的是JDK所带的 jstack工具，可以把Java的所有线程的stack trace都打印出来. 用处非常的大，当应用出现一些状况的时候，比如某个模块不执行， 锁竞争、CPU占用非常高等问题， 又没有足够的log信息可以分析，那么可以查看stack trace信息，看看线程都被阻塞或者运行在那些代码上，然后定位问题所在.

gdb调试和core dump文件的生成

- -
1、生成core dump文件的方法：.   $  ulimit -c //查看是否为0.     这样在程序崩溃以后会在当前目录生成一个core.xxxx的文件. 2、调试core dump文件.     生成了core.xxx文件以后.   $  gdb ./应用程序  core.xxxx.   就会恢复现场到你的程序崩溃的那一刻.

centos7使用lldb调试netcore应用转储dump文件 - czd890 - 博客园

- -
centos7下安装lldb，dotnet netcore 进程生成转储文件，并使用lldb进行分析. 随着netcore应用在linux上部署的应用越来越多，碰到cpu 100%，内存暴涨的情况也一直偶有发生，在windows平台下进程管理器右键转储，下载到本地使用windbg或者直接vs分析都比较方便.

并发之痛 Thread，Goroutine，Actor

- - 午夜咖啡
本文基于我在2月27日Gopher北京聚会演讲整理而成，进行了一些补充以及调整. 投稿给《高可用架构》公众号首发. 聊这个话题之前，先梳理下两个概念，几乎所有讲并发的文章都要先讲这两个概念：. 并发（concurrency） 并发的关注点在于任务切分. 举例来说，你是一个创业公司的CEO，开始只有你一个人，你一人分饰多角，一会做产品规划，一会写代码，一会见客户，虽然你不能见客户的同时写代码，但由于你切分了任务，分配了时间片，表现出来好像是多个任务一起在执行.

goroutine和线程区别

- - 学习日志
从调度上看，goroutine的调度开销远远小于线程调度开销. OS的线程由OS内核调度，每隔几毫秒，一个硬件时钟中断发到CPU，CPU调用一个调度器内核函数. 这个函数暂停当前正在运行的线程，把他的寄存器信息保存到内存中，查看线程列表并决定接下来运行哪一个线程，再从内存中恢复线程的注册表信息，最后继续执行选中的线程.

jstack Dump 日志文件分析

- - Web前端 - ITeye博客
jstack Dump 日志文件中的线程状态. dump 文件里，值得关注的线程状态有：. Deadlock（重点关注） . 执行中，Runnable   . Waiting on condition（重点关注） . Waiting on monitor entry（重点关注）. 暂停，Suspended.

在JVM发生FGC前后dump内存

- - 互联网 - ITeye博客
有时候web应用经常会发生FGC,我们想知道FGC把那些对象给回收了，思路很简单就是看看FGC之前内存中有那些实例，FGC之后内存中又有那些实例，通过前后的比较，我们就能很容易知道FGC回收了那些实例，当然我们可以手工去dump内存，在FGC发生之前dump一下内存，再在FGC发生之后dump一下内存，但是这dump的时间点不好把握，能否让JVM自动去dump就更好了.

jmap转换gcore的dump文件

- - 开源软件 - ITeye博客
使用gdb生成gcore快照文件. sudo gdb -q --pid=4990 【此处省略乱七八糟的输出内容】. --pid后面跟着的是jvm的进程id. 这里调用命令生成gcore的dump文件. detach是用来断开与jvm的连接的. quit简单了，退出gdb模式. 用jmap转换gcore的dump文件变成hprof.

【分布式系统工程实现】Bigtable Merge-Dump存储引擎

- XiaoHui - NOSQL Notes
单机存储引擎解决单机读写问题，Merge-Dump存储引擎设计成一种通用的存储引擎，同时支持数据写入，随机读取和顺序扫描功能. 顺序扫描功能应用很广，比如MapReduce批处理，同一个广告主的所有关键词广告统计，用户浏览所有的收藏信息，淘宝卖家管理大量的商品等. 简单的KV系统只需要支持随机读取，而类似Bigtable这样的通用表格系统需要考虑基于主键的顺序扫描功能.

HBase在淘宝主搜索的Dump中的性能调优

- - 搜索技术博客－淘宝
目前HBase已经运用于淘宝主搜索的全量和增量的数据存储，有效的减低的数据库的压力，增强了业务扩展的能力. Dump系统的特点是要求在短时间内处理大量数据，对延时要求高. 在实施这个项目过程中，我们积累了一些优化的实践，抛砖引玉，供大家参考. 环境：Hadoop CDH3U4 + HBase 0.92.1.