踩坑记： Go 服务灵异 panic

[felix021]

这个坑比较新鲜，周一刚填完，还冒着冷气。

- 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 实在太低，所以就耽搁了一段时间 <del>且不用担心背 P0 的锅</del>。

- 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)
    }
  }
}()
...

改起来倒是很简单，赶在这个 <del>需要上班的</del> 周日下午发了车，晚上就捉到了一个 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)

欢迎关注

   ▄▄▄▄▄▄▄   ▄      ▄▄▄▄ ▄▄▄▄▄▄▄  
   █ ▄▄▄ █ ▄▀ ▄ ▀██▄ ▀█▄ █ ▄▄▄ █  
   █ ███ █  █  █  █▀▀▀█▀ █ ███ █  
   █▄▄▄▄▄█ ▄ █▀█ █▀█ ▄▀█ █▄▄▄▄▄█  
   ▄▄▄ ▄▄▄▄█  ▀▄█▀▀▀█ ▄█▄▄   ▄    
   ▄█▄▄▄▄▄▀▄▀▄██   ▀ ▄  █▀▄▄▀▄▄█  
   █ █▀▄▀▄▄▀▀█▄▀█▄▀█████▀█▀▀█ █▄  
    ▀▀  █▄██▄█▀  █ ▀█▀ ▀█▀ ▄▀▀▄█  
   █▀ ▀ ▄▄▄▄▄▄▀▄██  █ ▄████▀▀ █▄  
   ▄▀▄▄▄ ▄ ▀▀▄████▀█▀  ▀ █▄▄▄▀▄█  
   ▄▀▀██▄▄  █▀▄▀█▀▀ █▀ ▄▄▄██▀ ▀   
   ▄▄▄▄▄▄▄ █ █▀ ▀▀   ▄██ ▄ █▄▀██  
   █ ▄▄▄ █ █▄ ▀▄▀ ▀██  █▄▄▄█▄  ▀  
   █ ███ █ ▄ ███▀▀▀█▄ █▀▄ ██▄ ▀█  
   █▄▄▄▄▄█ ██ ▄█▀█  █ ▀██▄▄▄  █▄  

填一下最后的问题：如果是一个空串，指针 Data 的值就是 nil，所以出现了 nil pointer dereference 。

[leon0903]

好文章

[gouchaoer]

好文

[frye]

学到了，很有深度啊

[reus]

你们没有开 -race 的测试？

全文缩写成一句话：读写竞态。

[AngryPanda]

可以，扫码就算了

[mornlight]

if b := s[i]; b < utf8.RuneSelf {

如果是 length 问题，panic 的这一行应该报 index 越界，为什么会是 nil pointer 呢？

[felix021]

@mornlight 有一个 special case~

[sagaxu]

不同语言的 memory model 差异还是很大的，JVM 上倒是能保证引用赋值是原子操作。

[felix021]

@sagaxu 嗯，但是在 go 这里 string 是传值(这个 struct 包含 data 和 len)而不是传引用

[iugo]

在 Go 入门中曾明确写 SliceHeader 的三部分, 但没有提 StringHeader.

不说深究 Go 的运行时了, 把所有官方包好好看看就足够对 Go 提升认识了. (当然还要有空翻翻标准)

[felix021]

@iugo 对，所以有一个 tricky 但是很有用的小技巧，就是用 unsafe.Pointer 在 string 和[]byte 之间互转。

[whoami9894]

我发现如果删除 go func 里的 sleep，编译器会直接把 go func 里的循环优化掉

```
func main() {
var s string
go func() {
i := 1
for {
i = 1 - i
if i == 0 {
s = FIRST
} else {
s = SECOND
}
}
}()

for {
fmt.Println(s)
time.Sleep(10)
}
}
```

[aladdindingding]

求需要掌握到怎么样才可以做到这样独立排查问题。。

[shynome]

感觉是程序有问题，为了一点性能到处用引用导致的问题

[lxml]

strings 和[]byte 这个转换一定要引入 unsafe 包才行总感觉怪怪的，但是我看官方的 strings.builder 也这么干

[SingeeKing]

@lxml #15 因为默认情况下直接转换会导致 byte 切片复制（因为自己不一定可以保证转换后原来的 byte slice 不再修改）。因此在自己可以保证不再更改原 byte slice 时会导致 O(n) 时间被浪费，所以只能用 unsafe 来直接强制转换了……

[drackzy]

大佬!

[felix021]

@aladdindingding 慢慢来，一方面打好基础(知道有什么是什么为什么)，另一方面不要放过工作中遇到的问题，从小问题开始攒经验，以及看看别人是怎么解决问题的，也会有帮助

[felix021]

@shynome 不是，原实现是一个请求一个 goroutine 处理，后来有限时的需要，拆了个任务出来，但是没有做好 race 检测，导致留了坑。

[liulaomo]

这个和 string 完全无关，写任何数据都应该避免数据竞争。

[labulaka521]

顶一个

[ypcs03]

不管啥类型并发的时候都应该考虑 lock 啊 不知道踩过多少次这样的坑了

[guanghe123]

8 加 mutex 锁那里，如果另一个 worker 读 StepName 的话是不需要 mutex 锁吗？感觉这样写的时候依旧可以读，读写依旧会冲突啊，还是我哪里理解错了...

[felix021]

@guanghe123 读的时候也要的，正文里没写完整，感谢补充

[gfreezy]

Rust 可以避免这个问题，这种情况直接编译不过

[felix021]

@gfreezy 学习曲线有点陡峭，以及公司整体基础设施不支持，短期内没办法……

[abbycin]

就这？

[will0404]

学到了有用的东西

[CoderGeek]

最近打算看看 go 扫了扫文章 感觉又劝退了 哈哈哈

[Sngo]

学习了

[andyangyu]

可以问下楼主 go 版本是多少么? 我在 1.14.4 下跑楼主提供的 poc 测试没有复现

[dokia]

@andyangyu 我用 1.14 版本复现出来了。刚开始我打印到屏幕上，打印的太快，没有看到异常 case 。把信息重定向到文件里面，就能看到上面楼主介绍的各种 bad case 了。

顺便赞一下楼主，魔鬼隐藏在细节中。

[banishee]

真尼玛🐂🍺

[felix021]

@dokia 我加上 grep -v 剩下的全是 badcase😏

[andyangyu]

@dokia 多谢大佬提醒, 疏忽了, 不过项目里面应该很少有并发操作一个 string 类型变量的情况吧