踩坑记#2： Go 服务锁死

[felix021]

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

---

前方低能

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

点开报警群，一串异常赫然在目：

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

再点开报警详情页一看：

---

排爆

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

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

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

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

对于异常的机器，从监控上可以看到，其 CPU 占用陡降至很低的值（约 2.5%）：

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

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

• 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 了，只可惜很快就装逼失败 —— 因为这个进程已经不响应任何请求了。

---

减压

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

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

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

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

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

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

---

深挖

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

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

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

$ sudo perf top

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

捞了一下代码，这个 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>……

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

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

再后面就是上游系统的 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 宣称的“抢占式调度”啊！

实际上 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 就可以破功了（试试看？）。

（被 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

---

欢迎关注

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

---

参考链接

1. 如何定位 golang 进程 hang 死的 bug
2. 关于 Go1.14 ，你一定想知道的性能提升与新特性
3. Go 语言原本：6.7 协作与抢占

[janxin]

刚刚看到一半还在想这个问题不是在 1.14 不存在了啊，调度器会抢占调度死循环 goroutine

[yangbonis]

看到 D 还以为是 D 状态进程，看完感觉和 D 状态进程异曲同工啊。

[felix021]

@yangbonis 哈哈 只是个巧合，给内部项目随便起的代号

[felix021]

@janxin 对，但是死循环本身还在，会推迟问题暴露的时间，比如可能会表现为 CPU 占用越来很高，但是处理性能很差、直到把机器搞挂

[stevefan1999]

厲害厲害

[yangbonis]

我估计写 C 的可能会反问，为什么死循环能不导致进程卡死？信号？哈哈。

[xmge]

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]

输入 price 是负数为什么会出现死循环。

[Ingo]

@xmge 标准的二分查找就是 start <= end，负数也不会死循环。

[FutherAll]

奥，我知道了，-1 除 2 是 0

[Ingo]

@FutherAll end 是-1，start 是 0，mid 每次都是 0

[Ingo]

二分查找看似简单，实际上还是有不少边界条件要处理的，比如有重复元素时返回左边界还是右边界，元素不存在时返回插入位置等变种

[dreampuf]

精彩

[saberlong]

1.14 刚发布没多久时，看到别人发的［ Go1.14 以下版本 WaitGroup 一个奇怪的问题］。问题原因一样，很有意思。

[lance6716]

感谢分享，不过面试怼 hard，真实业务写个二分都有 bug，这真的好吗

[labulaka521]

@lance6716 hhhh

[felix021]

@lance6716 哈哈哈，这说的有点打脸啊，不过还是嘴硬一下:

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

2. 上游代码确实是有 bug 的，程序员说到底还是人。公司这么大，我们每天都会收到各种各样的事故报告，这也是我们不断学习进步的一种方式

[matrix67]

@lance6716 扎心了，当初的面试官应该背一个 C 吧。

[newtype0092]

典型的小问题埋大坑哈哈。
同意 LZ 说的，这个二分问题不大，感觉要说主要问题应该是接口测试的 case 不完善吧，毕竟负数异常值还是挺常规的 case 。

上面提到面试想到，在面试的时候，经常被问到“你工作中遇到什么难题？怎么解决的？”，其实经常就是这样的场景，但是给面试官讲了以后，对方很容易产生“不就是没有验证参数么”这种只吃最后一口的感觉，完全当作一个小问题而忽略了过程，甚至自己很久以后复盘的时候也有这种感觉，所以写篇文章记录一下还是挺有意义的。

[lance6716]

@felix021 感觉代码写的不好鸭，试了试-1 只能响应越过 config 右边界的情况，越过 config 左边界、以及 config 里面有空洞都会死循环

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

看看这个有没有啥问题，就当刷 leetcode 了😂

[felix021]

@lance6716 不用这么麻烦，只要加一个 if price < 0 { panic() } 就好了

[felix021]

@lance6716 说到底是个 防御性编程 要防得多严的问题，所有 case 都写，代码就很冗余，很多 case 本来是应当在上层保证不出现的

[lance6716]

@felix021 这函数输入的约定也太脆弱了…

满足“在有序数组查找，找不到就输出-1”的二分查找不是很常见的吗，只不过现在数组元素的查找 key 是个区间罢了。我想贵司要是拿这个做面试题，大多数面试者都会顺便把“冗余”case 考虑到🤣实际工作中反而就变懒了

[Ingo]

@lance6716 老哥，我和你看法一致。这个二分查找使用 mid 作为循环条件，但是没有任何必要性

[iceheart]

这是特意发帖来甩锅么？
明明就是二分查找的 bug 。
代码里已经有逻辑来表示查找失败的情况下返回-1 了,可是事实上并没被执行到。
没找到就死循环？没见过这种二分法。

[felix021]

@iceheart 你觉得是就是吧，你开心就好 :)

[SingeeKing]

「 Go 语言原本」收藏了，近期开始看，感谢

（不过竟然停止维护了，感觉写的真的挺好的，有些可惜

[xsen]

@felix021 很明显就是二分的 bug 。价格有负数的么？！这不是很明显
另外，扯了一大堆没用的——找个 bug 绕一大圈，本来就很简单的问题（除了稍微难重现）

[xsen]

而且，很明显对二分的测试用例就很明显有问题。很明显的 int 型数据，负数竟然都没覆盖到，不可思议

[waruqi]

看到字节那 就知道下面要发小广告了，现在头条人人都是 hr 哈

[felix021]

@waruqi 没办法，业务发展快，缺人呀……

[mornlight]

在生产上遇到过同样的问题，找到原因后学乖了，Go 的服务所有接口都不响应+有一个核心被吃满，就是这个问题没跑。

[xwhxbg]

道理我都懂为啥不用标准库自带的 Search 呢？标准库的 slice 的 Search 就是 binary search 呀。

[felix021]

@xwhxbg 这是简化后的代码，repo 的代码比较复杂，不适合直接用库

[vindurriel]

unit test 和 code review 没做好