这个坑比拟陈腐,周一刚填完,还冒着冷气。

- 1 -

在字节跳动,咱们线上服务的所有 log 都通过对立的日志库采集到流式日志服务、落地 ES 集群,配上字节云超(sang)级(xin)强(bing)大(kuang)的监控能力,每一条 panic log 都能够触发一个打给值班同学的电话。

所以咱们经常不选电话,只选飞书 ↓↓↓

但毕竟是 panic,大部分 case 都会迅速被就地正法,除了多数排查吃力、又不对线上产生太大影响的,比方这一个:

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 兜住(不会把服务搞挂),而且呈现频率很低(每天几次甚至没有),思考到在每天数百亿申请中的占比,解决它的 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.goWHAT THEF*CK...WHATWHATWHATF*CKGOGC...

尽管没看到 panic,然而的确看到了点奇怪的货色(严正声明:不是故意要吐槽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 的并发读写会呈现这种景象呢?

这就得从 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:一些如同没什么用的冷常识
  • [译] C程序员该晓得的内存常识 (1)

欢送关注