21

踩坑记：Go服务灵异panic

 3 years ago
source link: https://studygolang.com/articles/29922
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

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

- 1 -

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

所以我们常常不选电话，只选 飞书 ↓↓↓

zu6Zfir.png!web

但毕竟是 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 的锅

。

faq6n2b.png!web

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

VjMRjeu.png!web

找到对应的 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 里装了什么呢？

eiiIrmJ.png!web

于是代码就变成了这样：

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 这一行注释掉……

BRbyYjr.png!web

作为一个追求极致的 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 呢？

YfieUbf.png!web

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

EBF3ii7.png!web

虽然没看到 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，不过文中已经给了足够多的工具，你能想到怎么办吗？


report

Recommend

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK