如何定位 golang 進程 hang 死的 bug

這是一個建立於 的文章，其中的資訊可能已經有所發展或是發生改變。

之前在 golang 群裡有人問過為什麼程式會莫名其妙的 hang 死然後不再響應任何請求。單核 cpu 打滿。

這個特徵和我們公司的某個系統曾經遇到的情況很相似，內部經過了很長時間的定位分析總結，期間還各種閱讀 golang 的 runtime 和 gc 代碼，最終才定位到是業務裡出現了類型下面這樣的代碼：

package mainimport "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 mainimport (    "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=13. 沒有系統調用

由於沒有系統調用，不是系統調用導致的鍋，所以我們沒有辦法藉助 strace 之類的工具看程式是不是 hang 在系統調用上。而 gcwaiting=1 實際上並不能幫我們定位到問題到底出現在哪裡。

然後就剩卡死在 for 迴圈上了，密集的 for 迴圈一般會導致一個 cpu 核心被打滿。如果之前做過系統編程的同學應該對 perf 這個工具很瞭解，可以使用：

perf top

對 cpu 的使用方式進行採樣，這樣我們就可以對 cpu 使用排名前列的程式函數進行定位。實際上 perf top 的執行結果也非常直觀：

  99.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：

https://github.com/gin-gonic/gin/issues/1086

從 perf 定位到函數，再用 pid attach 到進程，找到正在執行迴圈的 goroutine，然後結合 locals 的列印一路 next。

問題定位 over。

最後一行小字：感謝之前毛總在 golang 群的指導。

本文行文倉促，應該還是難免疏漏，如果你覺得哪裡寫的有問題，或者對文末提到的毛總頂禮膜拜，再或者對即將進入 k8s 的 json 解析庫 jsoniter 非常感性趣，想要深入瞭解 jsoniter 作者大牛的心路曆程，那麼你有下面幾個選擇：

1.加入b站和毛總學習先進姿勢水平

2.加入滴滴和 jsoniter 作者大牛 @taowen 做同事

3.加入滴滴來噴本文作者

簡曆可以發送到：caochunhui@didichuxing.com