字節(jié)跳動踩坑記#2：Go 服務(wù)鎖死

再挖個墳，講講去年踩的另一個坑。

== 前方低能 ==

那是去年7月的一天，被透過落地玻璃的宇宙中心五道口的夕陽照著的正在工位搬磚的我，突然聽到一陣騷亂，轉(zhuǎn)頭一看，收到奪命連環(huán)call的D同學反饋，流量嚴重異常。

點開報警群，一串異常赫然在目：

[?規(guī)則?]：「流量波動過大(嚴重)?」

[?報警上下文?]：change：-70.38%

值班人：D（不是我）

報警方式：電話&Lark

報警URL：報警詳情頁

再點開報警詳情頁一看：

== 排爆?==

解釋一下：在字節(jié)跳動，我們有一個基于OpenTSDB的metrics平臺（時序數(shù)據(jù)庫），用于采集和查詢各項監(jiān)控指標。

圖中是一個流量源的請求QPS，在短時間內(nèi)從 7k 暴降至 2k，從而觸發(fā)了報警規(guī)則。

除了流量源之外，在這個指標上我們還有機房、Server IP等其他tag；通過這些tag，我們發(fā)現(xiàn)：

• 來自所有流量源的QPS都在暴降

• 所有機房的QPS都在暴降

• 按IP看，許多機器的QPS降到0，但部分機器仍在正常接客

對于異常的機器，從監(jiān)控上可以看到，其CPU占用陡降至很低的值（約2.5%）：

于是這條線索讓我們把問題范圍縮小到某臺機器上。

進一步的排查情況情況是：

• ssh可以正常登錄，看起來OS沒啥問題

• 通過 lsof 可以看到，進程仍然在監(jiān)聽業(yè)務(wù)端口，只是不響應(yīng)請求
  

• top看到該進程在第一位，占了 99.8%的cpu，有點奇怪

• 注：這是一臺40核的物理機，top里 99.8% cpu表示進程占滿了1個核心，和前面的CPU監(jiān)控遙相呼應(yīng)。

PID??USER???  RES??%CPU? COMMAND316??user??968497??99.8??./service??1? root? ? 3796???0.0? systemd

雖然尚未定位到問題，但至少進一步把問題縮小到進程級別了。

既然是 go 程序的問題，那當然是要搬出神器?pprof?了，只可惜很快就裝逼失敗?——?因為這個進程已經(jīng)不響應(yīng)任何請求了。

== 減壓 ==

此時距故障發(fā)生已經(jīng)過了 15 分鐘，對于廣告業(yè)務(wù)，不能正常處理請求，對應(yīng)的就是真金白銀的損失。

但這個case以前沒出現(xiàn)過，一時半會又定位不了病根，大家都壓力山大。

在這種情況下，經(jīng)驗豐富的老司機們一定不會忘記的，就是壓箱底的大招 —— 重啟大法。

由于線上是大面積機器異常，我們隨便找了一臺機器重啟該進程，很快，這臺機器就開始正常接客了。

于是我們留下幾臺異常機器（保留現(xiàn)場備查）、從服務(wù)注冊中摘掉，并將其余異常機器全部重啟，暫時恢復了業(yè)務(wù)。

但病根未除，問題隨時可能復辟，還得繼續(xù)。

== 深挖 ==

前面說到，在top中看到，D項目的進程CPU占用率是100%，跑滿了一個CPU。

這是一個奇怪的現(xiàn)象，說明它并不是簡單地陷入死鎖，而是在反復執(zhí)行一些任務(wù)，這意味著，如果我們知道它在跑什么，可能就找到病因了。

這時候老司機W同學祭出了 linux 的 perf 命令

$?sudo?perf?top

幸福來的太突然，連函數(shù)名都給出來了，送命題秒變送分題

撈了一下代碼，這個 GetXXX 是一個二分查找的函數(shù)，根據(jù)輸入的價格，查詢對應(yīng)價格區(qū)間的相關(guān)配置，大概長這樣：

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?&&?mid?len(config)?{????????if?price?????????????end?=?mid?-?1????????}?else?if?price?>=?config[mid].right?{????????????start?=?mid?+?1????????}?else?{????????????return?config[mid].value????????}????????mid?=?(start?+?end)?/?2    }????return?-1}

按說這么簡單的代碼，線上跑了至少也幾個月了，不應(yīng)該有啥BUG，按照胡爾莫斯·柯南的教誨，排除一切不可能的，真相只有一個，那就是：輸入的價格是個負數(shù)。

負的價格？這不由得讓我想起了中行的某款理財產(chǎn)品……

當然這還只是個推論，在日記里三省吾身的胡適告訴我們，要大膽假設(shè)，小心求證。

實錘起來倒也很簡單，到上游的數(shù)據(jù)庫去查了一下，確實出現(xiàn)了負的價格。

再后面就是上游系統(tǒng)的BUG了，通過日志記錄發(fā)現(xiàn)在17:44確實有價格被改成負數(shù)，排查代碼確認，Web UI及對應(yīng)的后端代碼是有合法性校驗的，但是提供的 API 漏了，最終導致了這次事故。

既然找到了病根，修復起來就簡單了：

• 修復API代碼，加上合法性校驗

• 修復數(shù)據(jù)庫里的無效數(shù)據(jù)

• GetXXX里加上無效價格檢測（防御性編程）
  

== 填坑 ==

業(yè)務(wù)的坑是填完了，但是技術(shù)的坑還沒：為什么一個死循環(huán)會導致進程卡死呢？

按照調(diào)度的常識來推理，一個線程（或goroutine）不應(yīng)該阻塞其他線程的執(zhí)行。

比如運行下面這段代碼，可以看到，進程并沒有卡死，第一個 for 循環(huán)確實會不斷輸出 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)    }}

這說明“卡死”的原因還沒有這么簡單。

這樣簡單的代碼無法復現(xiàn)前面的問題，還是要把死循環(huán)放到復雜場景下才能復現(xiàn)，比如加入前述 D 項目的代碼里，簡單粗暴直接有效。

通過加上 GODEBUG 環(huán)境變量：

$?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

這就形成了閉環(huán)：gc需要STW，但是這個goroutine在死循環(huán)，無法被中斷，而其他goroutine已經(jīng)被中斷、等待gc完成，最終導致了這個局面。

可以在前述代碼里手動觸發(fā) gc 實錘一下：現(xiàn)象和線上完全一致。

var?i?int64?=?0
func?main()?{????go?func()?{????????for?{????????????fmt.Println(atomic.LoadInt64(&i))????????????time.Sleep(time.Millisecond?*?500)????????????runtime.GC()?//手動觸發(fā)GC????????}    }()????for?{????????atomic.AddInt64(&i,?1)    }}

但還沒完 —— 以上現(xiàn)象似乎并不符合 go 宣稱的“搶占式調(diào)度”?。?/p>

實際上 Go 實現(xiàn)的是一個 Cooperating Scheduler（協(xié)作式調(diào)度器）。一般而言，協(xié)作式調(diào)度器需要線程（準確地說是協(xié)程）主動放棄CPU來實現(xiàn)調(diào)度（runtime.Gosched()，對應(yīng) python/java 的 yield），但 Go 的 runtime 會在函數(shù)調(diào)用判斷是否要擴展?？臻g的同時，檢測 G 的搶占flag，從而實現(xiàn)了一個看起來像是搶占式調(diào)度的scheduler。

這還有個小問題?—— 上面的代碼里不是調(diào)用了 atomic.AddInt64 么？這個倒是簡單，通過??go?tool compile -S?main.go?可以看到，AddInt64 已經(jīng)被 inline 了；但只要在這里再加上個 fmt.Println 就可以破功了（試試看？）。

（被inline了的AddInt64）

== 收尾 ==

最后，如果你發(fā)現(xiàn)前面的代碼怎么都不能復現(xiàn) —— 那你一定是在用 go 1.14+ 了，這個版本實現(xiàn)了一個基于 SIGURG 信號的搶占式調(diào)度，再也不怕死循環(huán)/密集計算搞死 gc 了（不過代價是，出現(xiàn)死循環(huán)導致的性能下降問題更難排查了），對此感興趣的同學推薦學習《Go語言原本：6.7 協(xié)作與搶占》，詳見文末“閱讀原文”。

簡單總結(jié)一下：

1. 二分查找可能會死循環(huán)；

2. 在 go 1.13 及以下版本，死循環(huán)/密集計算會導致調(diào)度問題；

3. 特別是遇到 gc 的情況，可能會鎖死進程；

4. 在Linux下可以用perf top來做 profiling；

參考鏈接

[1]?如何定位 golang 進程 hang 死的 bug

https://xargin.com/how-to-locate-for-block-in-golang/

[2]?關(guān)于 Go1.14，你一定想知道的性能提升與新特性

https://gocn.vip/topics/9611

[3]?Go語言原本：6.7 協(xié)作與搶占

https://changkun.de/golang/zh-cn/part2runtime/ch06sched/preemption/

推薦閱讀

• 字節(jié)跳動踩坑記：Go 服務(wù)內(nèi)存暴漲