Jul
18
踩坑记: Go 服务灵异 panic
这个坑比较新鲜,周一刚填完,还冒着冷气。
- 1 -
在字节跳动,我们线上服务的所有 log 都通过统一的日志库采集到流式日志服务、落地 ES 集群,配上字节云超(sang)级(xin)强(bing)大(kuang)的监控能力,每一条 panic log 都可以触发一个打给值班同学的电话。
所以我们常常不选电话,只选飞书 ↓↓↓
但毕竟是 panic,大部分 case 都会迅速被就地正法,除了少数排查费劲、又不对线上产生太大影响的,比如这一个:
注:为了方便阅读,略有简化。
你看,它可以被 recover 兜住(不会把服务搞挂),而且出现频率很低(每天几次甚至没有),考虑到在每天数百亿请求中的占比,解决它的 ROI 实在太低,所以就耽搁了一段时间且不用担心背 P0 的锅。
- 2 -
其实之前 S 同学和我都关注过这个 panic ,从上面的 Error log 可以看到,错误发生在调用 json.Marshal 的时候,调用方的代码大概长这样:
注:实际map有更多key/value,这里略作简化。
看这代码,第一反应是:这**也能 panic ?
找到对应的 json 库源码(encode.go第880行,对应下面第5行):
—— 也只是从string里逐个读取字符,看着并没什么猫饼。
由于 panic 发生在官方 json 库里,不适合修改并部署到全量机器;引入第三方 json 库又涉及很多依赖问题,所以当时没再跟进。
直到最近 panic 频率逐渐升高, H 和 L 同学实在看不下去了。
- 3 -
L 同学的思路是,既然这个 panic 能被 recover 兜住,那为什么不看看 panic 时这个 map 里装了什么呢?
于是代码就变成了这样:
然后 panic 顺利转移到了 log.Warnf 这一行[doge]
- 4 -
不管怎么说成功地转移了问题,只要把 log.Warnf 这一行注释掉……
作为一个追求极致的 ByteDancer,L 同学抵制住了诱惑并尝试了新的思路,既然从 panic log 看到是跪在了一个 string 上,那至少先看看是哪一个string:
改起来倒是很简单,赶在这个需要上班的 周日下午发了车,晚上就捉到了一个case。
通过线上 log,我们发现错误出现在 "step" 这个 key 上(log里有输出key、但没输出value),value 本应是 ctx.StepName 这个 string。
可是 string 这种看起来人畜无害的 immutable 的 type 为什么会导致 panic 呢?
- 5 -
通过走读代码得知,在遇到异常的时候,我们会往 ctx.StepName 写入这个异常点的名称,就像这样:
一边读一边写,有那么点并发的味道了。
考虑到我们为了降低媒体感知的超时率,将整个广告的召回流程包装成一个带时间限制的任务:
因此在一个请求流程中,确实可能会出现并发读写 ctx.StepName 这个 string object 的情况。
但如何实锤是这儿挖的坑呢?
- 6 -
在线上服务中直接验证这一点不太容易,但是 H 同学做了一个简单的 POC,大概像这样:
代码一跑起来就有点味道了:
虽然没看到 panic,但是确实看到了点奇怪的东西(严正声明:不是故意要吐槽GO的GC)。
再用 go 的 race detector 瞅瞅:
这下可算是实锤了。
- 7 -
那么为什么 string 的并发读写会出现这种现象呢?
这就得从 string 底层的数据结构说起了。在 go 的 reflect 包里有一个 type StringHeader ,对应的就是 string 在 go runtime的表示:
可以看到, string 由一个指针(指向字符串实际内容)和一个长度组成。
比如说我们可以这么玩弄 StringHeader:
对于这样一个 struct ,golang 无法保证原子性地完成赋值,因此可能会出现goroutine 1 刚修改完指针(Data)、还没来得及修改长度(Len),goroutine 2 就读取了这个string 的情况。
因此我们看到了 "WHAT" 这个输出 —— 这就是将 s 从 "F*CK" 改成 "WHAT THE" 时,Data 改了、Len 还没来得及改的情况(仍然等于4)。
至于 "F*CKGOGC" 则正好相反,而且显然是出现了越界,只不过越界访问的地址仍然在进程可访问的地址空间里。
- 8 -
既然问题定位到了,解决起来就很简单了。
最直接的方法是使用 sync.Mutex:
但 Mutex 性能不够好(lock does not scale with the number of the processors),对于这种读写冲突概率很小的场景,性能更好的方案是将 ctx.StepName 类型改成 atomic.Value,然后
注:也可以改成 *string 然后使用 atomic.StorePointer
实际上,Golang 不保证任何单独的操作是原子性的,除非使用 atomic 包里提供的原语或加锁。
- 9 -
大结局:周一下午 H 同学提交了修复代码并完成发布,这个 panic 就再没出现了。
总结一下:
* string 没有看起来那么人畜无害
* 并发的坑可以找 -race 帮帮忙
* 记得使用 mutex 或 atomic
最后留下一个小问题供思考:
这说了半天并没有完全复现 panic,不过文中已经给了足够多的工具,你能想到怎么办吗?
推荐阅读:
* 程序员面试指北:面试官视角
* 踩坑记:go服务内存暴涨
* TCP:学得越多越不懂
* UTF-8:一些好像没什么用的冷知识
* [译] C程序员该知道的内存知识 (1)
转载请注明出自 ,如是转载文则注明原出处,谢谢:)
RSS订阅地址: https://www.felix021.com/blog/feed.php 。
- 1 -
在字节跳动,我们线上服务的所有 log 都通过统一的日志库采集到流式日志服务、落地 ES 集群,配上字节云超(sang)级(xin)强(bing)大(kuang)的监控能力,每一条 panic log 都可以触发一个打给值班同学的电话。
所以我们常常不选电话,只选飞书 ↓↓↓
但毕竟是 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)
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 实在太低,所以就耽搁了一段时间
- 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)
...
}
data := map[string]interface{} {
"code": ctx.ErrorCode,
"message": ctx.Message,
"step": ctx.StepName,
}
msg, err := json.Marshal(data)
...
}
注:实际map有更多key/value,这里略作简化。
看这代码,第一反应是:这**也能 panic ?
找到对应的 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 {
...
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 里装了什么呢?
于是代码就变成了这样:
defer func() {
if p := recover(); p != nil {
log.Warnf("Error: %v, data: %v", p, data)
}
}()
data := map[string]...
if p := recover(); p != nil {
log.Warnf("Error: %v, data: %v", p, data)
}
}()
data := map[string]...
然后 panic 顺利转移到了 log.Warnf 这一行[doge]
- 4 -
不管怎么说成功地转移了问题,只要把 log.Warnf 这一行注释掉……
作为一个追求极致的 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)
}
}
}()
...
defer func() {
if p := recover(); p != nil {
for k, v := range data {
log.Warnf("CatchMe: k=%v", k)
log.Warnf("CatchMe: v=%v", v)
}
}
}()
...
改起来倒是很简单,赶在这个
通过线上 log,我们发现错误出现在 "step" 这个 key 上(log里有输出key、但没输出value),value 本应是 ctx.StepName 这个 string。
可是 string 这种看起来人畜无害的 immutable 的 type 为什么会导致 panic 呢?
- 5 -
通过走读代码得知,在遇到异常的时候,我们会往 ctx.StepName 写入这个异常点的名称,就像这样:
const STEP_XX = "XX"
func XX(...) {
if err := process(); err != nil {
ctx.StepName = STEP_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()
}
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)
}
}
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
...
WHAT THE
F*CK
...
WHAT
WHAT
WHAT
F*CKGOGC
...
虽然没看到 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那行)
==================
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
}
Data uintptr
Len int
}
可以看到, string 由一个指针(指向字符串实际内容)和一个长度组成。
比如说我们可以这么玩弄 StringHeader:
s := "hello"
p := *(*reflect.StringHeader)(unsafe.Pointer(&s))
fmt.Println(p.Len)
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
}
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,不过文中已经给了足够多的工具,你能想到怎么办吗?
推荐阅读:
* 程序员面试指北:面试官视角
* 踩坑记:go服务内存暴涨
* TCP:学得越多越不懂
* UTF-8:一些好像没什么用的冷知识
* [译] C程序员该知道的内存知识 (1)
欢迎扫码关注:
转载请注明出自 ,如是转载文则注明原出处,谢谢:)
RSS订阅地址: https://www.felix021.com/blog/feed.php 。
acrossing
2020-7-27 09:50
重现了
felix021
2020-7-26 14:20
填一下最后的问题:如果是一个空串,指针 Data 的值就是 nil,所以出现了 nil pointer dereference 。
acrossing
2020-7-25 15:46
go1.12,测试了例子,没有重现呢
felix021 回复于 2020-7-26 14:09
重定向到文件,或者grep滤掉正常的输出
分页: 1/1 1