如何定位 golang 程式 hang 死的 bug

之前在 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 的執行結果也非常直觀：

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