之前在 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:
從 perf 定位到函數,再用 pid attach 到進程,找到正在執行循環的 goroutine,然后結合 locals 的打印一路 next。
問題定位 over。