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

踩坑记: Go 服务灵异 panic

  •  2
     
  •   felix021 · 26 天前 · 2656 次点击

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

    - 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 条附言  ·  25 天前
    填一下最后的问题:如果是一个空串,指针 Data 的值就是 nil,所以出现了 nil pointer dereference 。
    35 条回复    2020-07-20 14:18:02 +08:00
    leon0903
        1
    leon0903   26 天前
    好文章
    gouchaoer
        2
    gouchaoer   26 天前
    好文
    frye
        3
    frye   26 天前
    学到了,很有深度啊
    reus
        4
    reus   26 天前   ❤️ 5
    你们没有开 -race 的测试?

    全文缩写成一句话:读写竞态。
    AngryPanda
        5
    AngryPanda   26 天前 via Android
    可以,扫码就算了
    mornlight
        6
    mornlight   26 天前
    if b := s[i]; b < utf8.RuneSelf {

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

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

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