关于linux:踩坑记Go服务灵异panic

0次阅读

共计 3831 个字符，预计需要花费 10 分钟才能阅读完成。

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

在字节跳动，咱们线上服务的所有 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 的锅~~。

其实之前 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 同学切实看不下去了。

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]

不管怎么说胜利地转移了问题，只有把 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 呢？

通过走读代码得悉，在遇到异样的时候，咱们会往 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 的状况。

但如何实锤是这儿挖的坑呢？

在线上服务中间接验证这一点不太容易，然而 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 那行）

这下可算是实锤了。

那么为什么 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” 则正好相同，而且显然是呈现了越界，只不过越界拜访的地址依然在过程可拜访的地址空间里。

既然问题定位到了，解决起来就很简略了。

最间接的办法是应用 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 包里提供的原语或加锁。

大结局：周一下午 H 同学提交了修复代码并实现公布，这个 panic 就再没呈现了。

总结一下：

string 没有看起来那么人畜有害
并发的坑能够找 -race 帮帮忙
记得应用 mutex 或 atomic

最初留下一个小问题供思考：

这说了半天并没有齐全复现 panic，不过文中曾经给了足够多的工具，你能想到怎么办吗？

举荐浏览：

程序员面试指北：面试官视角
踩坑记：go 服务内存暴涨
TCP：学得越多越不懂
UTF-8：一些如同没什么用的冷常识
[译] C程序员该晓得的内存常识 (1)

正文完

linux

发表至： linux

2020-07-18

0

关于linux:大数据开发Linux系统入门之netstat-命令学习

关于linux:速度快性能好压缩神器-zstd

借助URLOS快速安装ApachePHP56网站环境

关于linux:Linux中bashrc与bashprofile的对比

关于消息队列:谈谈消息队列的流派

关于linux:踩坑记Go服务灵异panic

– 1 –

– 2 –

– 3 –

– 4 –

– 5 –

– 6 –

– 7 –

– 8 –

– 9 –

欢送关注

站内搜索