如何定位 golang 进程 hang 死的 bug

原创

wx62ccd9cc616d1 2022-09-25 08:07:56 ©著作权

©著作权归作者所有：来自51CTO博客作者wx62ccd9cc616d1的原创作品，请联系作者获取转载授权，否则将追究法律责任

之前在 golang 群里有人问过为什么程序会莫名其妙的 hang 死然后不再响应任何请求。单核 cpu 打满。

这个特征和我们公司的某个系统曾经遇到的情况很相似，内部经过了很长时间的定位分析总结，期间还各种阅读 golang 的 runtime 和 gc 代码，最终才定位到是业务里出现了类型下面这样的代码：

package main

import "runtime"

func main() {
    var ch = make(chan int, 100)
    go func() {
        for i := 0; i < 100; i++ {
            ch <- 1
            if i == 88 {
                runtime.GC()
            }
        }
    }()

    for {
        // the wrong part
        if len(ch) == 100 {
            sum := 0
            itemNum := len(ch)
            for i := 0; i < itemNum; i++ {
                sum += <-ch
            }
            if sum == itemNum {
                return
            }
        }
    }

}

在 main goroutine 里循环判断 ch 里是否数据被填满，在另一个 goroutine 里把 100 条数据塞到 ch 里。看起来程序应该是可以正常结束的对不对？

感兴趣的话你可以自己尝试运行一下。实际上这个程序在稍微老一些版本的 golang 上是会卡死在后面这个 for 循环上的。原因呢？

使用：

GODEBUG="schedtrace=300,scheddetail=1" ./test1

应该可以看到这时候 gcwaiting 标记为 1。所以当初都怀疑是 golang gc 的 bug。。但最终折腾了半天才发现还是自己的代码的问题。

因为在 for 循环中没有函数调用的话，编译器不会插入调度代码，所以这个执行 for 循环的 goroutine 没有办法被调出，而在循环期间碰到 gc，那么就会卡在 gcwaiting 阶段，并且整个进程永远 hang 死在这个循环上。并不再对外响应。

当然，上面这段程序在最新版本的 golang 1.8/1.9 中已经不会 hang 住了(实验结果，没有深究原因)。某次更新说明中官方声称在密集循环中理论上也会让其它的 goroutine 有被调度的机会，那么我们选择相信官方，试一下下面这个程序：

package main

import (
    "fmt"
    "io"
    "log"
    "net/http"
    "runtime"
    "time"
)

func main() {
    runtime.GOMAXPROCS(runtime.NumCPU())
    go server()
    go printNum()
    var i = 1
    for {
        // will block here, and never go out
        i++
    }
    fmt.Println("for loop end")
    time.Sleep(time.Second * 3600)
}

func printNum() {
    i := 0
    for {
        fmt.Println(i)
        i++
    }
}

func HelloServer(w http.ResponseWriter, req *http.Request) {
    io.WriteString(w, "hello, world!\n")
}

func server() {
    http.HandleFunc("/", HelloServer)
    err := http.ListenAndServe(":12345", nil)

    if err != nil {
        log.Fatal("ListenAndServe: ", err)
    }
}

运行几秒之后 curl 一发：

curl localhost:12345

感觉还是不要再相信官方了。研究研究之后不小心写出了这样的 bug 怎么定位比较好。首先分析一下这种类型 bug 发生时的程序特征：

1. 卡死在 for 循环上
2. gcwaiting=1
3. 没有系统调用

由于没有系统调用，不是系统调用导致的锅，所以我们没有办法借助 strace 之类的工具看程序是不是 hang 在系统调用上。而 gcwaiting=1 实际上并不能帮我们定位到问题到底出现在哪里。

然后就剩卡死在 for 循环上了，密集的 for 循环一般会导致一个 cpu 核心被打满。如果之前做过系统编程的同学应该对 perf 这个工具很了解，可以使用：

perf top

对 cpu 的使用情况进行采样，这样我们就可以对 cpu 使用排名前列的程序函数进行定位。实际上 perf top 的执行结果也非常直观：

.52%  ffff                     [.] main.main
   0.06%  [kernel]                 [k] __do_softirq
   0.05%  [kernel]                 [k] 0x00007fff81843a35
   0.03%  [kernel]                 [k] mpt_put_msg_frame
   0.03%  [kernel]                 [k] finish_task_switch
   0.03%  [kernel]                 [k] tick_nohz_idle_enter
   0.02%  perf                     [.] 0x00000000000824d7
   0.02%  [kernel]                 [k] e1000_xmit_frame
   0.02%  [kernel]                 [k] VbglGRPerform

你看，我们的程序实际上是卡在了 main.main 函数上。一发命令秒级定位。

妈妈再也不用担心我的程序不小心写出死循环了。实际上有时候我的一个普通循环为什么变成了死循环并不是像上面这样简单的 demo 那样好查，这时候你还可以用上 delve，最近就帮 jsoniter 定位了一个类似上面这样的 bug：