map 并发崩溃一例：顺便吐槽 Go 打印堆栈不友好

清华大佬耗费三个月吐血整理的几百G的资源，免费分享！....>>>

某系统中有类似下面这样的代码：

package main import ( "sync" "time" ) type resp struct {
	k string v string } func main() {
	res := fetchData()
    log.Print(res)
} func rpcwork() resp { // do some rpc work return resp{}
} func fetchData() (map[string]string, error) { var result = map[string]string{} // result is k -> v var keys = []string{"a", "b", "c"} var wg sync.WaitGroup var m sync.Mutex for i := 0; i < len(keys); i++ {
		wg.Add(1) go func() {
			m.Lock() defer m.Unlock() defer wg.Done() // do some rpc resp := rpcwork()

			result[resp.k] = resp.v
		}()
	}

	waitTimeout(&wg, time.Second) return result, nil } func waitTimeout(wg *sync.WaitGroup, timeout time.Duration) bool {
	c := make(chan struct{}) go func() { defer close(c)
		wg.Wait()
	}() select { case <-c: return false // completed normally case <-time.After(timeout): return true // timed out }
}

线上会偶现崩溃(concurrent write and iteration)，但其负责人声称一定是离职员工的锅，连代码都不愿意看。

这里的代码我已经简化过了，相信你大概可以看出来，这里的 waitgroup 使用不恰当，若下游系统发生超时时，该 waitgroup 其实并没有完成，这也就意味着，其子任务也并没有全部完成。虽然在 fetchData 内部对 map 的修改加了写锁，但若下游超时，在 fetchData 返回后，fetchData 内部启动的 goroutine 仍然可能对返回的 map 进行修改。

当 map 对象同时进行加锁的 write 和不加锁的读取时，也会发生崩溃。不加锁的读取发生在什么地方呢？其实就是这里例子的 log.Print。如果你做个 json.Marshal 之类的，效果也差不多。

至于为什么是偶发，超时本来也不是经常发生的，看起来这个 bug 就变成了一个偶现 bug。

和这个 bug 类似的还有在打印 context 对象的时候，参考这里^[1]。

我们再顺便控诉一下 Go 本身，这种 map 并发崩溃的 bug 对很多人造成了困扰，按说崩溃的时候会打印导致崩溃的 goroutine 栈，但为什么还是一个值得总结的问题呢？

是因为 Go 在崩溃时，其实并不能完整地打印导致崩溃的因果关系，参考这里^[2]。

这个 issue 中同时也给了下面这段代码，只有在 go run -race 时，才能看到导致 throw 的真正原因。

package main import ( "sync" ) var x map[int]string = make(map[int]string) func f(s string, wg *sync.WaitGroup) {
	x[0] = s
	wg.Done()
} func g(s string, wg *sync.WaitGroup) {
	x[1] = s
	wg.Done()
} func main() { for { var wg sync.WaitGroup
		wg.Add(2) go f("Hello", &wg) go g("Playground", &wg)
		wg.Wait()
	}
}

下面这个崩溃栈只能看到 main.g(你运行的时候，也可能只能看到 main.f)。

~/test ❯❯❯ go run mmmm.go
fatal error: concurrent map writes

goroutine 48 [running]:
runtime.throw(0x1074091, 0x15)
	/usr/local/go/src/runtime/panic.go:774 +0x72 fp=0xc000030758 sp=0xc000030728 pc=0x1024fb2
runtime.mapassign_fast64(0x1060d00, 0xc000064000, 0x1, 0xc000066048)
	/usr/local/go/src/runtime/map_fast64.go:101 +0x350 fp=0xc000030798 sp=0xc000030758 pc=0x100dcd0
main.g(0x1072f92, 0xa, 0xc0000680f0)
	/Users/didi/test/mmmm.go:15 +0x46 fp=0xc0000307c8 sp=0xc000030798 pc=0x10525f6
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:1357 +0x1 fp=0xc0000307d0 sp=0xc0000307c8 pc=0x104c001
created by main.main
	/Users/didi/test/mmmm.go:24 +0xbb

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc0000680f8)
	/usr/local/go/src/runtime/sema.go:56 +0x42
sync.(*WaitGroup).Wait(0xc0000680f0)
	/usr/local/go/src/sync/waitgroup.go:130 +0x64
main.main()
	/Users/didi/test/mmmm.go:25 +0xc9
exit status 2

下面这样才能看到真正的原因：

~/test ❯❯❯ go run -race mmmm.go
==================
WARNING: DATA RACE
Write at 0x00c00008c000 by goroutine 7:
  runtime.mapassign_fast64()
      /usr/local/go/src/runtime/map_fast64.go:92 +0x0
  main.g()
      /Users/didi/test/mmmm.go:15 +0x63

Previous write at 0x00c00008c000 by goroutine 6:
  runtime.mapassign_fast64()
      /usr/local/go/src/runtime/map_fast64.go:92 +0x0
  main.f()
      /Users/didi/test/mmmm.go:10 +0x63

Goroutine 7 (running) created at:
  main.main()
      /Users/didi/test/mmmm.go:24 +0xee

Goroutine 6 (finished) created at:
  main.main()
      /Users/didi/test/mmmm.go:23 +0xb7
==================
fatal error: concurrent map writes

goroutine 67286 [running]:
runtime.throw(0x10ad440, 0x15)
	/usr/local/go/src/runtime/panic.go:774 +0x72 fp=0xc000094750 sp=0xc000094720 pc=0x105c272
runtime.mapassign_fast64(0x1099c20, 0xc00008c000, 0x0, 0x0)
	/usr/local/go/src/runtime/map_fast64.go:176 +0x364 fp=0xc000094790 sp=0xc000094750 pc=0x1044ed4
main.f(0x10abea9, 0x5, 0xc00017ffa0)
	/Users/didi/test/mmmm.go:10 +0x64 fp=0xc0000947c8 sp=0xc000094790 pc=0x108b184
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:1357 +0x1 fp=0xc0000947d0 sp=0xc0000947c8 pc=0x1084651
created by main.main
	/Users/didi/test/mmmm.go:23 +0xb8

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc00017ffa8)
	/usr/local/go/src/runtime/sema.go:56 +0x42
sync.(*WaitGroup).Wait(0xc00017ffa0)
	/usr/local/go/src/sync/waitgroup.go:130 +0xb1
main.main()
	/Users/didi/test/mmmm.go:25 +0xfd
exit status 2

如若在实践中碰到了类似的 bug，只能好好读代码，别无他法，甩锅给离职员工是解决不了问题的。

如果你手边的代码抽象程度比较高，比如函数的参数都是一些 interface，由运行期来决定，那可能要定位这种 bug 就更费劲一些。