踩坑記#2：Go服務鎖死
再挖個墳，講講去年踩的另一個坑。
前方低能
那是去年7月的一天，被透過落地玻璃的宇宙中心五道口的夕陽照着的正在工位搬磚的我，突然聽到一陣騷亂，轉頭一看，收到奪命連環call的D同學反饋，流量嚴重異常。
點開報警羣，一串異常赫然在目：
[規則]：「流量波動過大(嚴重) 」
[報警上下文]：change：-70.38%
值班人：D（不是我）
報警方式：電話&Lark
報警URL：報警詳情頁
再點開報警詳情頁一看：
排爆
解釋一下：在字節跳動，我們有一個基於OpenTSDB的metrics平臺（時序數據庫），用於採集和查詢各項監控指標。
圖中是一個流量源的請求QPS，在短時間內從 7k 暴降至 2k，從而觸發了報警規則。
除了流量源之外，在這個指標上我們還有機房、Server IP等其他tag；通過這些tag，我們發現：
- 來自所有流量源的QPS都在暴降
- 所有機房的QPS都在暴降
- 按IP看，許多機器的QPS降到0，但部分機器仍在正常接客
對於異常的機器，從監控上可以看到，其CPU佔用陡降至很低的值（約2.5%）：
於是這條線索讓我們把問題範圍縮小到某臺機器上。
進一步的排查情況情況是：
- ssh可以正常登錄，看起來OS沒啥問題
- 通過 lsof 可以看到，進程仍然在監聽業務端口，只是不響應請求
-
top看到該進程在第一位，佔了 99.8%的cpu，有點奇怪
- 注：這是一臺40核的物理機，top裏 99.8% cpu表示進程佔滿了1個核心，和前面的CPU監控遙相呼應。
PID USER RES %CPU COMMAND 316 user 968497 99.8 ./service 1 root 3796 0.0 systemd
雖然尚未定位到問題，但至少進一步把問題縮小到進程級別了。
既然是 go 程序的問題，那當然是要搬出神器 pprof 了，只可惜很快就裝逼失敗 —— 因爲這個進程已經不響應任何請求了。
減壓
此時距故障發生已經過了 15 分鐘，對於廣告業務，不能正常處理請求，對應的就是真金白銀的損失。
但這個case以前沒出現過，一時半會又定位不了病根，大家都壓力山大。
在這種情況下，經驗豐富的老司機們一定不會忘記的，就是壓箱底的大招 —— 重啓大法。
由於線上是大面積機器異常，我們隨便找了一臺機器重啓該進程，很快，這臺機器就開始正常接客了。
於是我們留下幾臺異常機器（保留現場備查）、從服務註冊中摘掉，並將其餘異常機器全部重啓，暫時恢復了業務。
但病根未除，問題隨時可能復辟，還得繼續。
深挖
前面說到，在top中看到，D項目的進程CPU佔用率是100%，跑滿了一個CPU。
這是一個奇怪的現象，說明它並不是簡單地陷入死鎖，而是在反覆執行一些任務，這意味着，如果我們知道它在跑什麼，可能就找到病因了。
這時候老司機W同學祭出了 linux 的 perf 命令
$ sudo perf top
幸福來的太突然，連函數名都給出來了，送命題秒變送分題[doge]
撈了一下代碼，這個 GetXXX 是一個二分查找的函數，根據輸入的價格，查詢對應價格區間的相關配置，大概長這樣：
type Item struct {
left int
right int
value int
}
var config = []*Item{
{0, 10, 1},
{10, 20, 2},
{20,100, 8},
{100, 1<<31, 10},
}
func GetXXX(price int) int {
start, end := 0, len(config)
mid := (start + end) / 2
for mid >= 0 && price < len(config) {
if price < config[mid].left {
end = mid - 1
} else if price >= config[mid].right {
start = mid + 1
} else {
return config[mid].value
}
mid = (start + end) / 2
}
return -1
}
按說這麼簡單的代碼，線上跑了至少也幾個月了，不應該有啥BUG，按照胡爾莫斯·柯南的教誨，排除一切不可能的，真相只有一個，那就是： 輸入的價格是個負數 。
負的價格？這不由得讓我想起了
……
當然這還只是個推論，在日記裏三省吾身的胡適告訴我們，要大膽假設，小心求證。
實錘起來倒也很簡單，到上游的數據庫去查了一下，確實出現了了負的價格。
再後面就是上游系統的BUG了，通過日誌記錄發現在17:44確實有價格被改成負數，排查代碼確認，Web UI及對應的後端代碼是有合法性校驗的，但是提供的 API 漏了，最終導致了這次事故。
既然找到了病根，修復起來就簡單了：
- 修復API代碼，加上合法性校驗
- 修復數據庫裏的無效數據
- GetXXX里加上無效價格檢測（防禦性編程）
填坑
業務的坑是填完了，但是技術的坑還沒：爲什麼一個死循環會導致進程卡死呢？
按照調度的常識來推理，一個線程（或goroutine）不應該阻塞其他線程的執行。
比如運行下面這段代碼，可以看到，進程並沒有卡死，第一個 for 循環確實會不斷輸出 i 的值。
var i int64 = 0
func main() {
go func() {
for {
fmt.Println(atomic.LoadInt64(&i))
time.Sleep(time.Millisecond * 500)
}
}()
for {
atomic.AddInt64(&i, 1)
}
}
這說明“卡死”的原因還沒有這麼簡單。
這樣簡單的代碼無法復現前面的問題，還是要把死循環放到複雜場景下才能復現，比如加入前述 D 項目的代碼裏，簡單粗暴直接有效。
通過加上 GODEBUG 環境變量：
$ GODEBUG="schedtrace=2000,scheddetail=1" ./service
可以看到有一個線索：gcwaiting=1
SCHED 2006ms: gomaxprocs=64 idleprocs=0 threads=8 spinningthreads=0 idlethreads=5 runqueue=0 gcwaiting=1 nmidlelocked=0 stopwait=1 sysmonwait=0
這就形成了閉環：gc需要STW，但是這個goroutine在死循環，無法被中斷，而其他goroutine已經被中斷、等待gc完成，最終導致了這個局面。
可以在前述代碼裏手動觸發 gc 實錘一下：現象和線上完全一致。
var i int64 = 0
func main() {
go func() {
for {
fmt.Println(atomic.LoadInt64(&i))
time.Sleep(time.Millisecond * 500)
runtime.GC() //手動觸發GC
}
}()
for {
atomic.AddInt64(&i, 1)
}
}
但還沒完 —— 以上現象似乎並不符合 go 宣稱的“搶佔式調度”啊！
實際上 Go 實現的是一個 Cooperating Scheduler（協作式調度器）。一般而言，協作式調度器需要線程（準確地說是協程）主動放棄CPU來實現調度（runtime.Gosched()，對應 python/java 的 yield），但 Go 的 runtime 會在函數調用判斷是否要擴展棧空間的同時，檢測 G 的搶佔flag，從而實現了一個 看起來像 是搶佔式調度的scheduler。
這還有個小問題 —— 上面的代碼裏不是調用了 atomic.AddInt64 麼？這個倒是簡單，通過 go tool -S main.go 可以看到，AddInt64 已經被 inline 了；但只要在這裏再加上個 fmt.Println 就可以破功了（試試看？）。
（被inline了的AddInt64）
收尾
最後，如果你發現前面的代碼怎麼都不能復現 —— 那你一定是在用 go 1.14+ 了，這個版本實現了一個基於 SIGURG 信號的搶佔式調度，再也不怕死循環/密集計算搞死 gc 了（不過代價是，出現死循環導致的性能下降問題更難排查了），對此感興趣的同學推薦學習 《Go語言原本：6.7 協作與搶佔》 。
簡單總結一下：
- 二分查找可能會死循環；
- 在 go 1.13 及以下版本，死循環/密集計算會導致調度問題；
- 特別是遇到 gc 的情況，可能會鎖死進程；
- 在Linux下可以用perf top可以用來做 profiling；
學了這麼多，感覺又無用武之地？快來穿山甲，百萬級的QPS，各種酸爽的問題等着你。
~ 投遞鏈接 ~
投放研發工程師（上海）
https://job.toutiao.com/s/J8D...高級廣告研發工程師（北京）
https://job.toutiao.com/s/J8D...歡迎關注
參考鏈接
歡迎關注我們的微信公衆號，每天學習Go知識
