踩坑記：Go服務靈異panic

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

- 1 -

在字節跳動，咱們線上服務的全部 log 都經過統一的日誌庫採集到流式日誌服務、落地 ES 集羣，配上字節雲超(sang)級(xin)強(bing)大(kuang)的監控能力，每一條 panic log 均可以觸發一個打給值班同窗的電話。

因此咱們經常不選電話，只選飛書 ↓↓↓

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

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

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

你看，它能夠被 recover 兜住（不會把服務搞掛），並且出現頻率很低（天天幾回甚至沒有），考慮到在天天數百億請求中的佔比，解決它的 ROI 實在過低，因此就耽擱了一段時間 且不用擔憂背 P0 的鍋。

- 2 -

其實以前 S 同窗和我都關注過這個 panic ，從上面的 Error log 能夠看到，錯誤發生在調用 json.Marshal 的時候，調用方的代碼大概長這樣：

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

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

看這代碼，第一反應是：這**也能 panic ？

找到對應的 json 庫源碼（encode.go第880行，對應下面第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 發生在官方 json 庫裏，不適合修改並部署到全量機器；引入第三方 json 庫又涉及不少依賴問題，因此當時沒再跟進。

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

- 3 -

L 同窗的思路是，既然這個 panic 能被 recover 兜住，那爲何不看看 panic 時這個 map 裏裝了什麼呢？

因而代碼就變成了這樣：

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

而後 panic 順利轉移到了 log.Warnf 這一行[doge]

- 4 -

無論怎麼說成功地轉移了問題，只要把 log.Warnf 這一行註釋掉……

做爲一個追求極致的 ByteDancer，L 同窗抵制住了誘惑並嘗試了新的思路，既然從 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)
    }
  }
}()
...

改起來卻是很簡單，趕在這個 須要上班的 週日下午發了車，晚上就捉到了一個case。

經過線上 log，咱們發現錯誤出如今 "step" 這個 key 上（log裏有輸出key、但沒輸出value），value 本應是 ctx.StepName 這個 string。

但是 string 這種看起來人畜無害的 immutable 的 type 爲何會致使 panic 呢？

- 5 -

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

const STEP_XX = "XX"

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

一邊讀一邊寫，有那麼點併發的味道了。

考慮到咱們爲了下降媒體感知的超時率，將整個廣告的召回流程包裝成一個帶時間限制的任務：

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

所以在一個請求流程中，確實可能會出現併發讀寫 ctx.StepName 這個 string object 的狀況。

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

- 6 -

在線上服務中直接驗證這一點不太容易，可是 H 同窗作了一個簡單的 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.go
WHAT THE
F*CK
...
WHAT
WHAT
WHAT
F*CKGOGC
...

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

再用 go 的 race detector 瞅瞅：

$ go run -race poc.go >/dev/null    
==================
WARNING: DATA RACE
Write 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 的併發讀寫會出現這種現象呢？

這就得從 string 底層的數據結構提及了。在 go 的 reflect 包裏有一個 type StringHeader ，對應的就是 string 在 go runtime的表示：

type StringHeader struct {
    Data uintptr
    Len  int
}

能夠看到， string 由一個指針（指向字符串實際內容）和一個長度組成。

好比說咱們能夠這麼玩弄 StringHeader：

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

對於這樣一個 struct ，golang 沒法保證原子性地完成賦值，所以可能會出現goroutine 1 剛修改完指針（Data）、還沒來得及修改長度（Len），goroutine 2 就讀取了這個string 的狀況。

所以咱們看到了 "WHAT" 這個輸出 —— 這就是將 s 從 "F*CK" 改爲 "WHAT THE" 時，Data 改了、Len 還沒來得及改的狀況（仍然等於4）。

至於 "F*CKGOGC" 則正好相反，並且顯然是出現了越界，只不過越界訪問的地址仍然在進程可訪問的地址空間裏。

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

大結局：週一下午 H 同窗提交了修復代碼並完成發佈，這個 panic 就再沒出現了。

總結一下：

• string 沒有看起來那麼人畜無害
• 併發的坑能夠找 -race 幫幫忙
• 記得使用 mutex 或 atomic

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

這說了半天並無徹底復現 panic，不過文中已經給了足夠多的工具，你能想到怎麼辦嗎？

---

推薦閱讀：

• 程序員面試指北：面試官視角
• 踩坑記：go服務內存暴漲
• TCP：學得越多越不懂
• UTF-8：一些好像沒什麼用的冷知識
• [譯] Ｃ程序員該知道的內存知識 (1)

歡迎關注