踩坑记： Go 服务灵异 panic
这个坑比较新鲜，周一刚填完，还冒着冷气。
– 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) 注：为了方便阅读，略有简化。
你看，它可以被 recover 兜住（不会把服务搞挂），而且出现频率很低（每天几次甚至没有），考虑到在每天数百亿请求中的占比，解决它的 ROI 实在太低，所以就耽搁了一段时间 <del>且不用担心背 P0 的锅</del>。
– 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 ？
找到对应的 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 里装了什么呢？
于是代码就变成了这样：
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 这一行注释掉……
作为一个追求极致的 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 呢？
– 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 ... 
虽然没看到 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，不过文中已经给了足够多的工具，你能想到怎么办吗？
推荐阅读:
- 程序员面试指北：面试官视角
- 踩坑记：go 服务内存暴涨
- TCP：学得越多越不懂
- UTF-8：一些好像没什么用的冷知识
- [译] Ｃ程序员该知道的内存知识 (1)
欢迎关注
▄▄▄▄▄▄▄ ▄ ▄▄▄▄ ▄▄▄▄▄▄▄ █ ▄▄▄ █ ▄▀ ▄ ▀██▄ ▀█▄ █ ▄▄▄ █ █ ███ █ █ █ █▀▀▀█▀ █ ███ █ █▄▄▄▄▄█ ▄ █▀█ █▀█ ▄▀█ █▄▄▄▄▄█ ▄▄▄ ▄▄▄▄█ ▀▄█▀▀▀█ ▄█▄▄ ▄ ▄█▄▄▄▄▄▀▄▀▄██ ▀ ▄ █▀▄▄▀▄▄█ █ █▀▄▀▄▄▀▀█▄▀█▄▀█████▀█▀▀█ █▄ ▀▀ █▄██▄█▀ █ ▀█▀ ▀█▀ ▄▀▀▄█ █▀ ▀ ▄▄▄▄▄▄▀▄██ █ ▄████▀▀ █▄ ▄▀▄▄▄ ▄ ▀▀▄████▀█▀ ▀ █▄▄▄▀▄█ ▄▀▀██▄▄ █▀▄▀█▀▀ █▀ ▄▄▄██▀ ▀ ▄▄▄▄▄▄▄ █ █▀ ▀▀ ▄██ ▄ █▄▀██ █ ▄▄▄ █ █▄ ▀▄▀ ▀██ █▄▄▄█▄ ▀ █ ███ █ ▄ ███▀▀▀█▄ █▀▄ ██▄ ▀█ █▄▄▄▄▄█ ██ ▄█▀█ █ ▀██▄▄▄ █▄ 