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

踩坑记#2: Go 服务锁死

  •  1
     
  •   felix021 ·
    felix021 · 2020-06-25 22:01:06 +08:00 · 4681 次点击
    这是一个创建于 1610 天前的主题,其中的信息可能已经有所发展或是发生改变。

    接着上一篇-内存暴涨坑再挖个坟,讲讲去年踩的另一个坑。


    前方低能

    那是去年 7 月的一天,被透过落地玻璃的宇宙中心五道口的夕阳照着的正在工位搬砖的我,突然听到一阵骚乱,转头一看,收到夺命连环 call 的 D 同学反馈,流量严重异常。

    点开报警群,一串异常赫然在目:

    [规则]:「流量波动过大(严重) 」 [报警上下文]:change:-70.38% 值班人:D (不是我) 报警方式:电话&Lark 报警 URL:报警详情页

    再点开报警详情页一看:

    metrics.jpg

    满脸高兴.png


    排爆

    解释一下:在字节跳动,我们有一个基于 OpenTSDB 的 metrics 平台(时序数据库),用于采集和查询各项监控指标。

    图中是一个流量源的请求 QPS,在短时间内从 7k 暴降至 2k,从而触发了报警规则。

    除了流量源之外,在这个指标上我们还有机房、Server IP 等其他 tag ;通过这些 tag,我们发现:

    • 来自所有流量源的 QPS 都在暴降
    • 所有机房的 QPS 都在暴降
    • 按 IP 看,许多机器的 QPS 降到 0,但部分机器仍正常

    对于异常的机器,从监控上可以看到,其 CPU 占用陡降至很低的值(约 2.5%):

    host-cpu.png

    于是这条线索让我们把问题范围缩小到某台机器上。

    进一步的排查情况情况是:

    • ssh 可以正常登录,看起来 OS 没啥问题
    • 通过 lsof 可以看到,进程仍然在监听业务端口,只是不响应请求
    • top 看到该进程在第一位,占了 99.8%的 cpu,有点奇怪
      • 注:这是一台 40 核的物理机,top 里 99.8% cpu 表示进程占满了 1 个核心,和前面的 CPU 监控遥相呼应。
    PID  USER     RES  %CPU  COMMAND
    316  user  968497  99.8  ./service
      1  root    3796   0.0  systemd
    

    虽然尚未定位到问题,但至少进一步把问题缩小到进程级别了。

    既然是 go 程序的问题,那当然是要搬出神器 pprof 了,只可惜很快就装逼失败 —— 因为这个进程已经不响应任何请求了。

    令人头秃.png


    减压

    此时距故障发生已经过了 15 分钟,对于广告业务,不能正常处理请求,对应的就是真金白银的损失。

    但这个 case 以前没出现过,一时半会又定位不了病根,大家都压力山大。

    在这种情况下,经验丰富的老司机们一定不会忘记的,就是压箱底的大招 —— 重启大法。

    由于线上是大面积机器异常,我们随便找了一台机器重启该进程,很快,这台机器就开始正常处理请求了。

    真香.jpeg

    于是我们留下几台异常机器(保留现场备查)、从服务注册中摘掉,并将其余异常机器全部重启,暂时恢复了业务。

    但病根未除,问题随时可能复现,还得继续。


    深挖

    前面说到,在 top 中看到,D 项目的进程 CPU 占用率是 100%,跑满了一个 CPU 。

    这是一个奇怪的现象,说明它并不是简单地陷入死锁,而是在反复执行一些任务,这意味着,如果我们知道它在跑什么,可能就找到病因了。

    这时候老司机 W 同学祭出了 linux 的 perf 命令

    $ sudo perf top
    

    perf-top.png

    幸福来的太突然,连函数名都给出来了,送命题秒变送分题[doge]

    送分题.png

    捞了一下代码,这个 GetXXX 是一个二分查找的函数,根据输入的价格,查询对应价格区间的相关配置,大概长这样:

    type Item struct {
        left int
        right int
        value int
    }
    
    var config = []*Item{
        {0, 10, 1},
        {10, 20, 2},
        {20,100, 8},
        {100, 1<<31, 10},
    }
    
    func GetXXX(price int) int {
        start, end := 0, len(config)
        mid := (start + end) / 2
        for mid >= 0 && mid < len(config) {
            if price < config[mid].left {
                end = mid - 1
            } else if price >= config[mid].right {
                start = mid + 1
            } else {
                return config[mid].value
            }
            mid = (start + end) / 2
        }
        return -1
    }
    

    按说这么简单的代码,线上跑了至少也几个月了,不应该有啥 BUG,按照胡尔莫斯·柯南的教诲,排除一切不可能的,真相只有一个,那就是:输入的价格是个负数

    负的价格?这不由得让我想起了<del>某行的某款割韭菜产品</del>……

    yuanyoubao.jpeg

    当然这还只是个推论,在日记里三省吾身的胡适告诉我们,要大胆假设,小心求证。

    实锤起来倒也很简单,到上游的数据库去查了一下,确实出现了负的价格。

    再后面就是上游系统的 BUG 了,通过日志记录发现在 17:44 确实有价格被改成负数,排查代码确认,Web UI 及对应的后端代码是有合法性校验的,但是提供的 API 漏了,最终导致了这次事故。

    既然找到了病根,修复起来就简单了:

    • 修复 API 代码,加上合法性校验
    • 修复数据库里的无效数据
    • GetXXX 里加上无效价格检测(防御性编程)

    填坑

    业务的坑是填完了,但是技术的坑还没:为什么一个死循环会导致进程卡死呢?

    按照调度的常识来推理,一个线程(或 goroutine )不应该阻塞其他线程的执行。

    比如运行下面这段代码,可以看到,进程并没有卡死,第一个 for 循环确实会不断输出 i 的值。

    var i int64 = 0
    
    func main() {
        go func() {
            for {
                fmt.Println(atomic.LoadInt64(&i))
                time.Sleep(time.Millisecond * 500)
            }
        }()
        for {
            atomic.AddInt64(&i, 1)
        }
    }
    

    这说明“卡死”的原因还没有这么简单。

    这样简单的代码无法复现前面的问题,还是要把死循环放到复杂场景下才能复现,比如加入前述 D 项目的代码里,简单粗暴直接有效。

    通过加上 GODEBUG 环境变量:

    $ GODEBUG="schedtrace=2000,scheddetail=1" ./service
    

    可以看到有一个线索:gcwaiting=1

    SCHED 2006ms: gomaxprocs=64 idleprocs=0 threads=8 spinningthreads=0 idlethreads=5 runqueue=0 gcwaiting=1 nmidlelocked=0 stopwait=1 sysmonwait=0

    这就形成了闭环:gc 需要 STW,但是这个 goroutine 在死循环,无法被中断,而其他 goroutine 已经被中断、等待 gc 完成,最终导致了这个局面。

    可以在前述代码里手动触发 gc 实锤一下:现象和线上完全一致。

    var i int64 = 0
    
    func main() {
        go func() {
            for {
                fmt.Println(atomic.LoadInt64(&i))
                time.Sleep(time.Millisecond * 500)
                runtime.GC() //手动触发 GC
            }
        }()
        for {
            atomic.AddInt64(&i, 1)
        }
    }
    

    但还没完 —— 以上现象似乎并不符合 go 宣称的“抢占式调度”啊!

    陷入沉思.jpeg

    实际上 Go 实现的是一个 Cooperating Scheduler (协作式调度器)。一般而言,协作式调度器需要线程(准确地说是协程)主动放弃 CPU 来实现调度( runtime.Gosched(),对应 python/java 的 yield ),但 Go 的 runtime 会在函数调用判断是否要扩展栈空间的同时,检测 G 的抢占 flag,从而实现了一个看起来像是抢占式调度的 scheduler 。

    这还有个小问题 —— 上面的代码里不是调用了 atomic.AddInt64 么?这个倒是简单,通过 go tool compile -S main.go 可以看到,AddInt64 已经被 inline 了;但只要在这里再加上个 fmt.Println 就可以破功了(试试看?)。

    go-inline.png

    (被 inline 了的 AddInt64 )

    收尾

    最后,如果你发现前面的代码怎么都不能复现 —— 那你一定是在用 go 1.14+ 了,这个版本实现了一个基于 SIGURG 信号的抢占式调度,再也不怕死循环 /密集计算搞死 gc 了(不过代价是,出现死循环导致的性能下降问题更难排查了),对此感兴趣的同学推荐学习《 Go 语言原本:6.7 协作与抢占》

    简单总结一下:

    1. 二分查找可能会死循环;
    2. 在 go 1.13 及以下版本,死循环 /密集计算会导致调度问题;
    3. 特别是遇到 gc 的情况,可能会锁死进程;
    4. 在 Linux 下可以用 perf top 来做 profiling ;

    学了这么多,感觉又无用武之地?快来穿山甲,百万级的 QPS,各种酸爽的问题等着你。

    ~ 投递链接 ~

    投放研发工程师(上海) https://job.toutiao.com/s/J8DRDyG

    高级广告研发工程师(北京) https://job.toutiao.com/s/J8DNwJY


    欢迎关注

    weixin2s.png

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

    参考链接

    1. 如何定位 golang 进程 hang 死的 bug
    2. 关于 Go1.14 ,你一定想知道的性能提升与新特性
    3. Go 语言原本:6.7 协作与抢占
    35 条回复    2020-07-06 07:21:57 +08:00
    janxin
        1
    janxin  
       2020-06-25 22:26:10 +08:00
    刚刚看到一半还在想这个问题不是在 1.14 不存在了啊,调度器会抢占调度死循环 goroutine
    yangbonis
        2
    yangbonis  
       2020-06-25 22:38:15 +08:00 via iPhone
    看到 D 还以为是 D 状态进程,看完感觉和 D 状态进程异曲同工啊。
    felix021
        3
    felix021  
    OP
       2020-06-25 22:42:52 +08:00
    @yangbonis 哈哈 只是个巧合,给内部项目随便起的代号
    felix021
        4
    felix021  
    OP
       2020-06-25 22:44:10 +08:00
    @janxin 对,但是死循环本身还在,会推迟问题暴露的时间,比如可能会表现为 CPU 占用越来很高,但是处理性能很差、直到把机器搞挂
    stevefan1999
        5
    stevefan1999  
       2020-06-25 22:49:36 +08:00
    厲害厲害
    yangbonis
        6
    yangbonis  
       2020-06-25 22:49:39 +08:00 via iPhone
    我估计写 C 的可能会反问,为什么死循环能不导致进程卡死?信号?哈哈。
    xmge
        7
    xmge  
       2020-06-25 23:12:38 +08:00   ❤️ 1
    for mid >= 0 && mid < len(config) {
    if price < config[mid].left {
    end = mid - 1
    } else if price >= config[mid].right {
    start = mid + 1
    } else {
    return config[mid].value
    }
    mid = (start + end) / 2
    }
    return -1
    }


    是不是这样就可以了呢?这里的代码是不是也应该修改呢?

    for start <= end {
    if price < config[mid].left {
    end = mid - 1
    } else if price >= config[mid].right {
    start = mid + 1
    } else {
    return config[mid].value
    }
    mid = (start + end) / 2
    }
    return -1
    }
    FutherAll
        8
    FutherAll  
       2020-06-26 00:15:37 +08:00 via iPhone
    输入 price 是负数为什么会出现死循环。
    Ingo
        9
    Ingo  
       2020-06-26 00:22:45 +08:00 via iPhone
    @xmge 标准的二分查找就是 start <= end,负数也不会死循环。
    FutherAll
        10
    FutherAll  
       2020-06-26 00:23:46 +08:00 via iPhone
    奥,我知道了,-1 除 2 是 0
    Ingo
        11
    Ingo  
       2020-06-26 00:23:56 +08:00 via iPhone
    @FutherAll end 是-1,start 是 0,mid 每次都是 0
    Ingo
        12
    Ingo  
       2020-06-26 00:28:01 +08:00 via iPhone
    二分查找看似简单,实际上还是有不少边界条件要处理的,比如有重复元素时返回左边界还是右边界,元素不存在时返回插入位置等变种
    dreampuf
        13
    dreampuf  
       2020-06-26 02:00:17 +08:00
    精彩
    saberlong
        14
    saberlong  
       2020-06-26 06:33:58 +08:00 via Android
    1.14 刚发布没多久时,看到别人发的[ Go1.14 以下版本 WaitGroup 一个奇怪的问题]。问题原因一样,很有意思。
    lance6716
        15
    lance6716  
       2020-06-26 07:49:21 +08:00 via Android   ❤️ 8
    感谢分享,不过面试怼 hard,真实业务写个二分都有 bug,这真的好吗
    labulaka521
        16
    labulaka521  
       2020-06-26 07:57:53 +08:00 via iPhone
    @lance6716 hhhh
    felix021
        17
    felix021  
    OP
       2020-06-26 11:19:40 +08:00 via Android
    @lance6716 哈哈哈,这说的有点打脸啊,不过还是嘴硬一下:

    1. 严格来说不算二分的 bug,因为业务场景下预期会由上游保证价格为正。即使加上了防御性代码,负的价格仍然是无法处理的,只是代码的健壮性确实不够

    2. 上游代码确实是有 bug 的,程序员说到底还是人。公司这么大,我们每天都会收到各种各样的事故报告,这也是我们不断学习进步的一种方式
    matrix67
        18
    matrix67  
       2020-06-26 11:33:56 +08:00
    @lance6716 扎心了,当初的面试官应该背一个 C 吧。
    newtype0092
        19
    newtype0092  
       2020-06-26 11:59:42 +08:00   ❤️ 1
    典型的小问题埋大坑哈哈。
    同意 LZ 说的,这个二分问题不大,感觉要说主要问题应该是接口测试的 case 不完善吧,毕竟负数异常值还是挺常规的 case 。

    上面提到面试想到,在面试的时候,经常被问到“你工作中遇到什么难题?怎么解决的?”,其实经常就是这样的场景,但是给面试官讲了以后,对方很容易产生“不就是没有验证参数么”这种只吃最后一口的感觉,完全当作一个小问题而忽略了过程,甚至自己很久以后复盘的时候也有这种感觉,所以写篇文章记录一下还是挺有意义的。
    lance6716
        20
    lance6716  
       2020-06-26 13:42:59 +08:00
    @felix021 感觉代码写的不好鸭,试了试-1 只能响应越过 config 右边界的情况,越过 config 左边界、以及 config 里面有空洞都会死循环

    https://play.golang.org/p/K9_KvGZQehR

    看看这个有没有啥问题,就当刷 leetcode 了😂
    felix021
        21
    felix021  
    OP
       2020-06-26 14:11:05 +08:00
    @lance6716 不用这么麻烦,只要加一个 if price < 0 { panic() } 就好了
    felix021
        22
    felix021  
    OP
       2020-06-26 14:12:56 +08:00
    @lance6716 说到底是个 防御性编程 要防得多严的问题,所有 case 都写,代码就很冗余,很多 case 本来是应当在上层保证不出现的
    lance6716
        23
    lance6716  
       2020-06-26 14:59:25 +08:00 via Android
    @felix021 这函数输入的约定也太脆弱了…

    满足“在有序数组查找,找不到就输出-1”的二分查找不是很常见的吗,只不过现在数组元素的查找 key 是个区间罢了。我想贵司要是拿这个做面试题,大多数面试者都会顺便把“冗余”case 考虑到🤣实际工作中反而就变懒了
    Ingo
        24
    Ingo  
       2020-06-26 20:05:28 +08:00 via iPhone
    @lance6716 老哥,我和你看法一致。这个二分查找使用 mid 作为循环条件,但是没有任何必要性
    iceheart
        25
    iceheart  
       2020-06-26 22:58:23 +08:00 via Android
    这是特意发帖来甩锅么?
    明明就是二分查找的 bug 。
    代码里已经有逻辑来表示查找失败的情况下返回-1 了,可是事实上并没被执行到。
    没找到就死循环?没见过这种二分法。
    felix021
        26
    felix021  
    OP
       2020-06-26 23:35:08 +08:00
    @iceheart 你觉得是就是吧,你开心就好 :)
    SingeeKing
        27
    SingeeKing  
       2020-06-27 02:45:14 +08:00
    「 Go 语言原本」收藏了,近期开始看,感谢

    (不过竟然停止维护了,感觉写的真的挺好的,有些可惜
    xsen
        28
    xsen  
       2020-06-27 06:37:13 +08:00
    @felix021 很明显就是二分的 bug 。价格有负数的么?!这不是很明显
    另外,扯了一大堆没用的——找个 bug 绕一大圈,本来就很简单的问题(除了稍微难重现)
    xsen
        29
    xsen  
       2020-06-27 06:39:51 +08:00
    而且,很明显对二分的测试用例就很明显有问题。很明显的 int 型数据,负数竟然都没覆盖到,不可思议
    waruqi
        30
    waruqi  
       2020-06-27 10:04:45 +08:00 via Android
    看到字节那 就知道下面要发小广告了,现在头条人人都是 hr 哈
    felix021
        31
    felix021  
    OP
       2020-06-27 10:21:56 +08:00 via Android
    @waruqi 没办法,业务发展快,缺人呀……
    mornlight
        32
    mornlight  
       2020-06-27 22:19:09 +08:00
    在生产上遇到过同样的问题,找到原因后学乖了,Go 的服务所有接口都不响应+有一个核心被吃满,就是这个问题没跑。
    xwhxbg
        33
    xwhxbg  
       2020-06-30 13:19:03 +08:00
    道理我都懂为啥不用标准库自带的 Search 呢?标准库的 slice 的 Search 就是 binary search 呀。
    felix021
        34
    felix021  
    OP
       2020-07-01 01:26:33 +08:00   ❤️ 1
    @xwhxbg 这是简化后的代码,repo 的代码比较复杂,不适合直接用库
    vindurriel
        35
    vindurriel  
       2020-07-06 07:21:57 +08:00 via iPhone
    unit test 和 code review 没做好
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   实用小工具   ·   2789 人在线   最高记录 6679   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 27ms · UTC 13:55 · PVG 21:55 · LAX 05:55 · JFK 08:55
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.