V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
felix021
V2EX  ›  程序员

踩坑记: Go 服务灵异 panic

  •  2
     
  •   felix021 ·
    felix021 · 2020-07-18 15:58:08 +08:00 · 3647 次点击
    这是一个创建于 431 天前的主题,其中的信息可能已经有所发展或是发生改变。

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

    - 1 -

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

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

    lark-only.png

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

    这个锅我不背 s.png

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

    奇了怪了打码 s.png

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

    葫芦里装逼 s.png

    于是代码就变成了这样:

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

    你懂我意思吧 s.png

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

    我怀疑你在逗我 s.png

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

    黑人问号 s.png

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


    推荐阅读:

    欢迎关注

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

    weixin2s.png

    第 1 条附言  ·  2020-07-19 22:03:33 +08:00
    填一下最后的问题:如果是一个空串,指针 Data 的值就是 nil,所以出现了 nil pointer dereference 。
    35 条回复    2020-07-20 14:18:02 +08:00
    leon0903
        1
    leon0903   2020-07-18 16:07:04 +08:00
    好文章
    gouchaoer
        2
    gouchaoer   2020-07-18 16:15:04 +08:00
    好文
    frye
        3
    frye   2020-07-18 16:27:33 +08:00
    学到了,很有深度啊
    reus
        4
    reus   2020-07-18 16:44:01 +08:00   ❤️ 5
    你们没有开 -race 的测试?

    全文缩写成一句话:读写竞态。
    AngryPanda
        5
    AngryPanda   2020-07-18 16:44:53 +08:00 via Android
    可以,扫码就算了
    mornlight
        6
    mornlight   2020-07-18 16:50:12 +08:00
    if b := s[i]; b < utf8.RuneSelf {

    如果是 length 问题,panic 的这一行应该报 index 越界,为什么会是 nil pointer 呢?
    felix021
        7
    felix021   2020-07-18 16:57:16 +08:00 via Android
    @mornlight 有一个 special case~
    sagaxu
        8
    sagaxu   2020-07-18 17:12:36 +08:00 via Android
    不同语言的 memory model 差异还是很大的,JVM 上倒是能保证引用赋值是原子操作。
    felix021
        9
    felix021   2020-07-18 17:14:11 +08:00 via Android
    @sagaxu 嗯,但是在 go 这里 string 是传值(这个 struct 包含 data 和 len)而不是传引用
    iugo
        10
    iugo   2020-07-18 17:15:22 +08:00
    在 Go 入门中曾明确写 SliceHeader 的三部分, 但没有提 StringHeader.

    不说深究 Go 的运行时了, 把所有官方包好好看看就足够对 Go 提升认识了. (当然还要有空翻翻标准)
    felix021
        11
    felix021   2020-07-18 17:24:51 +08:00 via Android
    @iugo 对,所以有一个 tricky 但是很有用的小技巧,就是用 unsafe.Pointer 在 string 和[]byte 之间互转。
    whoami9894
        12
    whoami9894   2020-07-18 17:42:12 +08:00   ❤️ 1
    我发现如果删除 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
        13
    aladdindingding   2020-07-18 18:07:12 +08:00
    求需要掌握到怎么样才可以做到这样独立排查问题。。
    shynome
        14
    shynome   2020-07-18 18:35:38 +08:00 via Android
    感觉是程序有问题,为了一点性能到处用引用导致的问题
    lxml
        15
    lxml   2020-07-18 18:57:27 +08:00 via Android
    strings 和[]byte 这个转换一定要引入 unsafe 包才行总感觉怪怪的,但是我看官方的 strings.builder 也这么干
    SingeeKing
        16
    SingeeKing   2020-07-18 19:12:51 +08:00   ❤️ 1
    @lxml #15 因为默认情况下直接转换会导致 byte 切片复制(因为自己不一定可以保证转换后原来的 byte slice 不再修改)。因此在自己可以保证不再更改原 byte slice 时会导致 O(n) 时间被浪费,所以只能用 unsafe 来直接强制转换了……
    drackzy
        17
    drackzy   2020-07-18 19:17:10 +08:00
    大佬!
    felix021
        18
    felix021   2020-07-18 19:37:39 +08:00 via Android
    @aladdindingding 慢慢来,一方面打好基础(知道有什么是什么为什么),另一方面不要放过工作中遇到的问题,从小问题开始攒经验,以及看看别人是怎么解决问题的,也会有帮助
    felix021
        19
    felix021   2020-07-18 19:38:56 +08:00 via Android   ❤️ 1
    @shynome 不是,原实现是一个请求一个 goroutine 处理,后来有限时的需要,拆了个任务出来,但是没有做好 race 检测,导致留了坑。
    liulaomo
        20
    liulaomo   2020-07-18 20:58:00 +08:00
    这个和 string 完全无关,写任何数据都应该避免数据竞争。
    labulaka521
        21
    labulaka521   2020-07-18 21:51:28 +08:00 via iPhone
    顶一个
    ypcs03
        22
    ypcs03   2020-07-18 21:52:13 +08:00
    不管啥类型并发的时候都应该考虑 lock 啊 不知道踩过多少次这样的坑了
    guanghe123
        23
    guanghe123   2020-07-18 23:26:39 +08:00   ❤️ 1
    8 加 mutex 锁那里,如果另一个 worker 读 StepName 的话是不需要 mutex 锁吗?感觉这样写的时候依旧可以读,读写依旧会冲突啊,还是我哪里理解错了...
    felix021
        24
    felix021   2020-07-18 23:46:24 +08:00 via Android   ❤️ 1
    @guanghe123 读的时候也要的,正文里没写完整,感谢补充
    gfreezy
        25
    gfreezy   2020-07-19 01:03:17 +08:00 via iPhone   ❤️ 1
    Rust 可以避免这个问题,这种情况直接编译不过
    felix021
        26
    felix021   2020-07-19 07:22:26 +08:00 via Android
    @gfreezy 学习曲线有点陡峭,以及公司整体基础设施不支持,短期内没办法……
    abbycin
        27
    abbycin   2020-07-19 09:17:45 +08:00 via Android
    就这?
    will0404
        28
    will0404   2020-07-19 11:03:29 +08:00
    学到了有用的东西
    CoderGeek
        29
    CoderGeek   2020-07-19 11:48:09 +08:00
    最近打算看看 go 扫了扫文章 感觉又劝退了 哈哈哈
    Sngo
        30
    Sngo   2020-07-19 12:55:49 +08:00 via iPhone
    学习了
    andyangyu
        31
    andyangyu   2020-07-20 09:52:49 +08:00
    可以问下楼主 go 版本是多少么? 我在 1.14.4 下跑楼主提供的 poc 测试没有复现
    dokia
        32
    dokia   2020-07-20 10:40:56 +08:00   ❤️ 1
    @andyangyu 我用 1.14 版本复现出来了。刚开始我打印到屏幕上,打印的太快,没有看到异常 case 。把信息重定向到文件里面,就能看到上面楼主介绍的各种 bad case 了。

    顺便赞一下楼主,魔鬼隐藏在细节中。
    banishee
        33
    banishee   2020-07-20 11:32:19 +08:00
    真尼玛🐂🍺
    felix021
        34
    felix021   2020-07-20 13:07:40 +08:00 via Android
    @dokia 我加上 grep -v 剩下的全是 badcase😏
    andyangyu
        35
    andyangyu   2020-07-20 14:18:02 +08:00
    @dokia 多谢大佬提醒, 疏忽了, 不过项目里面应该很少有并发操作一个 string 类型变量的情况吧
    关于   ·   帮助文档   ·   FAQ   ·   API   ·   我们的愿景   ·   广告投放   ·   感谢   ·   实用小工具   ·   2836 人在线   最高记录 5497   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 33ms · UTC 05:03 · PVG 13:03 · LAX 22:03 · JFK 01:03
    ♥ Do have faith in what you're doing.