序言
最近一位非常热心的网友建议结合demo来分析一下goroutine的调度器,而且还提供了一个demo代码,于是便有了本文,在此对这位网友表示衷心的感谢!
这位网友提供的demo程序可能有的gopher以前见过,已经知道了具体原因,但本文假定我们是第一次遇到这种问题,然后从零开始,通过一步一步的分析和定位,最终找到问题的根源及解决方案。
虽然本文不需要太多的背景知识,但最好使用过gdb或delve调试工具,了解汇编语言及函数调用栈当然就更好了。
本文我们需要重点了解下面这3个内容。
- 调试工具无法准确显示函数调用栈时如何找到函数调用链;
- 发生GC时,如何STOP THE WORLD;
- 什么时候抢占调度不会起作用以及如何规避。
本文的实验环境为AMD64 Linux + go1.12
Demo程序及运行现象
package main
import (
"fmt"
"runtime"
"time"
)
func deadloop() {
for {
}
}
func worker() {
for {
fmt.Println("worker is running")
time.Sleep(time.Second * 1)
}
}
func main() {
fmt.Printf("There are %d cores.\n", runtime.NumCPU())
go worker()
go deadloop()
i := 3
for {
fmt.Printf("main is running, i=%d\n", i)
i--
if i == 0 {
runtime.GC()
}
time.Sleep(time.Second * 1)
}
}
编译并运行,结果:
bobo@ubuntu:~/study/go$ ./deadlock
There are 4 cores.
main is running, i=3
worker is running
main is running, i=2
worker is running
worker is running
main is running, i=1
worker is running
程序运行起来打印了这几条信息之后就再也没有输出任何信息,看起来程序好像卡死了!
我们第一次遇到这种问题,该如何着手开始分析呢?
分析代码
首先来分析一下代码,这个程序启动之后将会在main函数中创建一个worker goroutine和一个deadloop goroutine,加上main goroutine,一共应该有3个用户goroutine,其中
- dealloop goroutine: 一直在执行一个死循环,并未做任何实际的工作;
- worker goroutine: 每隔一秒循环打印worker is running;
- main goroutine: 也一直在执行着一个循环,每隔一秒打印一下main is running,同时输出变量i的值并对i执行减减操作,当i等于0的时候会去调用runtime.GC函数触发垃圾回收。
因为我们目前掌握的知识有限,所以暂时看不出有啥问题,看起来一切都应该很正常才对,为什么会卡死呢?
分析日志
看不出程序有什么问题,我们就只能再来仔细看一下输出的日志信息。从日志信息可以看出,一开始main goroutine和worker 还很正常,但当打印了i = 1之后,main goroutine就再也没有输出信息了,而这之后worker也只打印了一次就没有再打印信息了。
从代码可以知道,打印了i = 1之后i就自减了1变成了0,i等于0之后就会去执行runtime.GC(),所以我们有理由怀疑卡死跟GC垃圾回收有关,怀疑归怀疑,我们需要拿出证据来证明它们确实有关才行。怎么找证据呢?
跟踪函数调用链
因为程序并没有退出,而是卡起了,我们会很自然的想到通过调试工具来看一下到底发生了什么事情。这里我们使用delve这个专门为Go程序定制的调试器。
使用pidof命令找到deadlock的进程ID,然后使用dlv attach上去,并通过goroutines命令查看程序中的goroutine
bobo@ubuntu:~/study/go$ pidof deadlock
2369
bobo@ubuntu:~/study/go$ sudo dlv attach 2369
Type 'help' for list of commands.
(dlv) goroutines
Goroutine 1 - User: /usr/local/go/src/runtime/mgc.go:1055 runtime.GC (0x416ab8)
Goroutine 2 - User: /usr/local/go/src/runtime/proc.go:302 runtime.gopark (0x429b2f)
Goroutine 3 - User: /usr/local/go/src/runtime/proc.go:302 runtime.gopark (0x429b2f)
Goroutine 4 - User: /usr/local/go/src/runtime/proc.go:302 runtime.gopark (0x429b2f)
Goroutine 5 - User: /usr/local/go/src/runtime/proc.go:307 time.Sleep (0x442a09)
Goroutine 6 - User: ./deadlock.go:10 main.deadloop (0x488f90) (thread 2372)
Goroutine 7 - User: /usr/local/go/src/runtime/proc.go:302 runtime.gopark (0x429b2f)
Goroutine 17 - User: /usr/local/go/src/runtime/proc.go:3005 runtime.exitsyscall (0x4307e6)
Goroutine 33 - User: /usr/local/go/src/runtime/proc.go:302 runtime.gopark (0x429b2f)
Goroutine 34 - User: /usr/local/go/src/runtime/proc.go:302 runtime.gopark (0x429b2f)
Goroutine 35 - User: /usr/local/go/src/runtime/proc.go:302 runtime.gopark (0x429b2f)
Goroutine 36 - User: /usr/local/go/src/runtime/proc.go:302 runtime.gopark (0x429b2f)
Goroutine 37 - User: /usr/local/go/src/runtime/proc.go:302 runtime.gopark (0x429b2f)
Goroutine 49 - User: /usr/local/go/src/runtime/proc.go:302 runtime.gopark (0x429b2f)
[14 goroutines]
(dlv)
从输出信息可以看到程序中一共有14个goroutine,其它的goroutine不用管,我们只关心那3个用户goroutine,容易看出它们分别是
Goroutine 1 - User: /usr/local/go/src/runtime/mgc.go:1055 runtime.GC (0x416ab8) #main goroutine
Goroutine 5 - User: /usr/local/go/src/runtime/proc.go:307 time.Sleep (0x442a09) #worker goroutine
Goroutine 6 - User: ./deadlock.go:10 main.deadloop (0x488f90) (thread 2372) #deadloop goroutine
因为我们怀疑卡死跟runtime.GC()函数调用有关,所以我们切换到Goroutine 1并使用backtrace命令(简写bt)查看一下main goroutine的函数调用栈:
(dlv) goroutine 1
Switched from 0 to 1 (thread 2371)
(dlv) bt
0 0x00000