字節(jié)跳動踩坑記#3：Go服務(wù)靈異panic

這個坑比較新鮮，剛填完，還冒著冷氣。

- 1?-

在字節(jié)跳動，我們服務(wù)的所有 log 都通過統(tǒng)一的日志庫采集到流式日志服務(wù)、落地 ES 集群，配上字節(jié)云超(sang)級(xin)強(bing)大(kuang)的監(jiān)控能力，每一條 panic log 都可以觸發(fā)一個打給值班同學(xué)的電話。

所以我們常常不選電話，只選飛書?↓↓↓

但畢竟是 panic，大部分 case 都會迅速被就地正法，除了少數(shù)排查費勁、又不對線上產(chǎn)生太大影響的，比如這一個：

Error:?invalid?memory?address?or?nil?pointer?dereferenceTraceback:goroutine 68532877 [running]:...src/encoding/json/encode.go:880?+0x59encoding/json.stringEncoder(0xcb9fead550,?...)...src/encoding/json/encode.go:298?+0xa5encoding/json.Marshal(0x1ecb9a0,?...).../path/to/util.SendData(0xca813cd300)

注：為了方便閱讀，略有簡化。

你看，它可以被 recover 兜住（不會把服務(wù)搞掛），而且出現(xiàn)頻率很低（每天幾次甚至沒有），考慮到在每天數(shù)百億請求中的占比，解決它的 ROI 實在太低，所以就耽擱了一段時間 且不用擔(dān)心背 P0 的鍋。

- 2?-

其實之前 S 同學(xué)和我都關(guān)注過這個 panic ，從上面的 Error log 可以看到，錯誤發(fā)生在調(diào)用 json.Marshal 的時候，調(diào)用方的代碼大概長這樣：

func SendData(...) {??data?:=?map[string]interface{}?{????"code":????ctx.ErrorCode,????"message": ctx.Message,????"step":????ctx.StepName,  }  msg,?err := json.Marshal(data)  ...}

注：實際map有更多key/value，這里略作簡化。

看這代碼，第一反應(yīng)是：這**也能 panic ？

找到對應(yīng)的 json?庫源碼（encode.go第880行，對應(yīng)下面第5行）：

func (e *encodeState) string(s string, escapeHTML bool) {  e.WriteByte('"')  start := 0  for i := 0; i < len(s); {    if b := s[i]; b < utf8.RuneSelf {      ...

—— 也只是從string里逐個讀取字符，看著并沒什么貓餅。

由于 panic 發(fā)生在官方 json?庫里，不適合修改并部署到全量機器；引入第三方 json 庫又涉及很多依賴問題，所以當(dāng)時沒再跟進(jìn)。

直到最近 panic 頻率逐漸升高， H 和 L 同學(xué)實在看不下去了。

- 3?-

L 同學(xué)的思路是，既然這個 panic 能被 recover 兜住，那為什么不看看 panic 時這個 map 里裝了什么呢？

于是代碼就變成了這樣：

defer?func() {??if?p?:=?recover();?p?!=?nil?{????log.Warnf("Error:?%v,?data:?%v",?p,?data)??}}()data?:=?map[string]...

然后 panic 順利轉(zhuǎn)移到了?log.Warnf?這一行?

- 4?-

不管怎么說成功地轉(zhuǎn)移了問題，只要把 log.Warnf 這一行注釋掉……

作為一個追求極致的 ByteDancer，L 同學(xué)抵制住了誘惑并嘗試了新的思路，既然從 panic log 看到是跪在了一個 string 上，那至少先看看是哪一個string：

data?:=?make(map[string]interface{})defer func() {  if p := recover(); p != nil {????for?k,?v?:= range data {??????log.Warnf("CatchMe:?k=%v",?k)??????log.Warnf("CatchMe:?v=%v",?v)????}??}}()...

改起來倒是很簡單，趕在這個?需要上班的?周日下午發(fā)了車，晚上就捉到了一個case。

通過線上 log，我們發(fā)現(xiàn)錯誤出現(xiàn)在?"step" 這個 key 上（log里有輸出key、但沒輸出value），value 本應(yīng)是 ctx.StepName 這個 string。

可是 string 這種看起來人畜無害的 immutable 的 type 為什么會導(dǎo)致 panic 呢？

- 5 -

通過走讀代碼得知，在遇到異常的時候，我們會往 ctx.StepName 寫入這個異常點的名稱，就像這樣：

const?STEP_XX?=?"XX"
func XX(...) {  if?err?:=?process();?err?!=?nil {????ctx.StepName = STEP_XX  }}

一邊讀一邊寫，有那么點并發(fā)的味道了。

考慮到我們?yōu)榱私档兔襟w感知的超時率，將整個廣告的召回流程包裝成一個帶時間限制的任務(wù)：

finished?:=?make(chan?struct{})timer?:=?time.NewTimer(duration)go?recall(finished)select {??case?<-finished:????sendResponse()??case?<-?timer.C:????sendTimeoutResponse()}

因此在一個請求流程中，確實可能會出現(xiàn)并發(fā)讀寫 ctx.StepName 這個 string object 的情況。

但如何實錘是這兒挖的坑呢？

- 6?-

在線上服務(wù)中直接驗證這一點不太容易，但是 H 同學(xué)做了一個簡單的 POC，大概像這樣：

const?(  FIRST  = "WHAT THE"??SECOND?=?"F*CK")
func main() {  var s string  go func() {    i := 1    for {      i = 1 - i??????if?i?==?0?{        s = FIRST      } else {        s = SECOND      }      time.Sleep(10)    }  }()
  for {    fmt.Println(s)    time.Sleep(10)  }}

代碼一跑起來就有點味道了：

$ go run poc.goWHAT THEF*CK...WHATWHATWHATF*CKGOGC...

雖然沒看到 panic，但是確實看到了點奇怪的東西（嚴(yán)正聲明：不是故意要吐槽GO的GC）。

再用 go 的 race detector 瞅瞅：

$ go run -race poc.go >/dev/null    ==================WARNING: DATA RACEWrite at 0x00c00011c1e0 by goroutine 7:  main.main.func1()????poc.go:19?+0x66（賦值那行）
Previous read at 0x00c00011c1e0 by main goroutine:  main.main()????poc.go:28?+0x9d（println那行）

?

這下可算是實錘了。

- 7 -

那么為什么 string 的并發(fā)讀寫會出現(xiàn)這種現(xiàn)象呢？

這就得從 string 底層的數(shù)據(jù)結(jié)構(gòu)說起了。在 go 的 reflect 包里有一個 type StringHeader ，對應(yīng)的就是 string 在 go runtime的表示：

type StringHeader struct {    Data uintptr    Len  int}

可以看到， string 由一個指針（指向字符串實際內(nèi)容）和一個長度組成。

比如說我們可以這么玩弄 StringHeader：

s?:=?"hello"p?:=?*(*reflect.StringHeader)(unsafe.Pointer(&s))fmt.Println(p.Len)

對于這樣一個?struct ，golang 無法保證原子性地完成賦值，因此可能會出現(xiàn)goroutine 1 剛修改完指針（Data）、還沒來得及修改長度（Len），goroutine 2 就讀取了這個string 的情況。

因此我們看到了 "WHAT" 這個輸出 —— 這就是將 s 從 "F*CK" 改成 "WHAT THE" 時，Data 改了、Len 還沒來得及改的情況（仍然等于4）。

至于 "F*CKGOGC" 則正好相反，而且顯然是出現(xiàn)了越界，只不過越界訪問的地址仍然在進(jìn)程可訪問的地址空間里。

- 8 -

既然問題定位到了，解決起來就很簡單了。

最直接的方法是使用 sync.Mutex：

func?(ctx *Context) SetStep(step string) {??ctx.Mutex.Lock()??defer ctx.Mutex.Unlock()??ctx.StepName = Step}

但 Mutex 性能不夠好（lock does not scale with the number of the processors），對于這種讀寫沖突概率很小的場景，性能更好的方案是將 ctx.StepName 類型改成?atomic.Value，然后

ctx.StepName.Store(step)

注：也可以改成 *string 然后使用 atomic.StorePointer

實際上，Golang 不保證任何單獨的操作是原子性的，除非使用 atomic 包里提供的原語或加鎖。

- 9 -

大結(jié)局：周一下午 H 同學(xué)提交了修復(fù)代碼并完成發(fā)布，這個 panic 就再沒出現(xiàn)了。

總結(jié)一下：

• string 沒有看起來那么人畜無害

• 并發(fā)的坑可以找?-race?幫幫忙

• 記得使用 mutex 或 atomic

最后留下一個小問題供思考：

這說了半天并沒有完全復(fù)現(xiàn)?panic，不過文中已經(jīng)給了足夠多的工具，你能想到怎么辦嗎？

推薦閱讀

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