实战分析一个运行起来会卡死的Go程序

序言

最近一位非常热心的网友建议结合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