map 并发崩溃一例

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

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 对象的时候，参考这里。

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

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

这个 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 就更费劲一些。