Jun
25
接着 上一篇-内存暴涨坑 再挖个坟,讲讲去年踩的另一个坑。
---
前方低能
那是去年7月的一天,被透过落地玻璃的宇宙中心五道口的夕阳照着的正在工位搬砖的我,突然听到一阵骚乱,转头一看,收到夺命连环call的D同学反馈,流量严重异常。
点开报警群,一串异常赫然在目:
再点开报警详情页一看:
---
排爆
解释一下:在字节跳动,我们有一个基于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监控遥相呼应。
虽然尚未定位到问题,但至少进一步把问题缩小到进程级别了。
既然是 go 程序的问题,那当然是要搬出神器 pprof 了,只可惜很快就装逼失败 —— 因为这个进程已经不响应任何请求了。
---
减压
此时距故障发生已经过了 15 分钟,对于广告业务,不能正常处理请求,对应的就是真金白银的损失。
但这个case以前没出现过,一时半会又定位不了病根,大家都压力山大。
在这种情况下,经验丰富的老司机们一定不会忘记的,就是压箱底的大招 —— 重启大法。
由于线上是大面积机器异常,我们随便找了一台机器重启该进程,很快,这台机器就开始正常处理请求了。
于是我们留下几台异常机器(保留现场备查)、从服务注册中摘掉,并将其余异常机器全部重启,暂时恢复了业务。
但病根未除,问题随时可能复现,还得继续。
---
深挖
前面说到,在top中看到,D项目的进程CPU占用率是100%,跑满了一个CPU。
这是一个奇怪的现象,说明它并不是简单地陷入死锁,而是在反复执行一些任务,这意味着,如果我们知道它在跑什么,可能就找到病因了。
这时候老司机W同学祭出了 linux 的 perf 命令
幸福来的太突然,连函数名都给出来了,送命题秒变送分题[doge]
捞了一下代码,这个 GetXXX 是一个二分查找的函数,根据输入的价格,查询对应价格区间的相关配置,大概长这样:
按说这么简单的代码,线上跑了至少也几个月了,不应该有啥BUG,按照胡尔莫斯·柯南的教诲,排除一切不可能的,真相只有一个,那就是:**输入的价格是个负数**。
负的价格?这不由得让我想起了中行的某款理财产品……
当然这还只是个推论,在日记里三省吾身的胡适告诉我们,要大胆假设,小心求证。
实锤起来倒也很简单,到上游的数据库去查了一下,确实出现了负的价格。
再后面就是上游系统的BUG了,通过日志记录发现在17:44确实有价格被改成负数,排查代码确认,Web UI及对应的后端代码是有合法性校验的,但是提供的 API 漏了,最终导致了这次事故。
既然找到了病根,修复起来就简单了:
* 修复API代码,加上合法性校验
* 修复数据库里的无效数据
* GetXXX里加上无效价格检测(防御性编程)
---
填坑
业务的坑是填完了,但是技术的坑还没:为什么一个死循环会导致进程卡死呢?
按照调度的常识来推理,一个线程(或goroutine)不应该阻塞其他线程的执行。
比如运行下面这段代码,可以看到,进程并没有卡死,第一个 for 循环确实会不断输出 i 的值。
这说明“卡死”的原因还没有这么简单。
这样简单的代码无法复现前面的问题,还是要把死循环放到复杂场景下才能复现,比如加入前述 D 项目的代码里,简单粗暴直接有效。
通过加上 GODEBUG 环境变量:
可以看到有一个线索:gcwaiting=1
这就形成了闭环:gc需要STW,但是这个goroutine在死循环,无法被中断,而其他goroutine已经被中断、等待gc完成,最终导致了这个局面。
可以在前述代码里手动触发 gc 实锤一下:现象和线上完全一致。
但还没完 —— 以上现象似乎并不符合 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 协作与抢占
转载请注明出自 ,如是转载文则注明原出处,谢谢:)
RSS订阅地址: https://www.felix021.com/blog/feed.php 。
---
前方低能
那是去年7月的一天,被透过落地玻璃的宇宙中心五道口的夕阳照着的正在工位搬砖的我,突然听到一阵骚乱,转头一看,收到夺命连环call的D同学反馈,流量严重异常。
点开报警群,一串异常赫然在目:
引用
[规则]:「流量波动过大(严重) 」
[报警上下文]:change:-70.38%
值班人:D(不是我)
报警方式:电话&Lark
报警URL:报警详情页
[报警上下文]: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
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
}
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,按照胡尔莫斯·柯南的教诲,排除一切不可能的,真相只有一个,那就是:**输入的价格是个负数**。
负的价格?这不由得让我想起了
当然这还只是个推论,在日记里三省吾身的胡适告诉我们,要大胆假设,小心求证。
实锤起来倒也很简单,到上游的数据库去查了一下,确实出现了负的价格。
再后面就是上游系统的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)
}
}
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)
}
}
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 协作与抢占
欢迎扫码关注:
转载请注明出自 ,如是转载文则注明原出处,谢谢:)
RSS订阅地址: https://www.felix021.com/blog/feed.php 。