#不要忽略 goroutine 的启动时间, for range 陷阱
原文地址 mp.weixin.qq.com
小菜刀的项目中需要将数据推给多个服务器，大致如下
1package main
2
3import (
4 "fmt"
5 "sync"
6)
7
8func mockSendToServer(url string) {
9 fmt.Printf("server url: %s\n", url)
10}
11
12func main() {
13 urls := []string{"0.0.0.0:5000", "0.0.0.0:6000", "0.0.0.0:7000"}
14 wg := sync.WaitGroup{}
15 for _, url := range urls {
16 wg.Add(1)
17 go func() {
18 defer wg.Done()
19 mockSendToServer(url)
20 }()
21 }
22 wg.Wait()
23}
请读者停来下思考一下，以上代码会得到什么样的输出。
1$ go run main.go
2server url: 0.0.0.0:7000
3server url: 0.0.0.0:7000
4server url: 0.0.0.0:7000
这个结果，是不是和你想的一样呢。那么，问题出在了哪里？为什么从 for 循环中传递的 url 变得相同了，且为数组中的最后一项 url。
原因分析
在 Go 中提供了非常好的程序分析工具，trace 和 pprof。trace 侧重于分析 goroutine 的调度，pprof 则侧重于程序的运行性能。为了更好地排查上述 bug 产生的原因，代码中新增了 trace 代码段。
1package main
2
3import (
4 "fmt"
5 "os"
6 "runtime/trace"
7 "sync"
8)
9
10func mockSendToServer(url string) {
11 fmt.Printf("server url: %s\n", url)
12}
13
14func main() {
15 f, err := os.Create("trace.out")
16 if err != nil {
17 panic(err)
18 }
19 defer f.Close()
20
21 err = trace.Start(f)
22 if err != nil {
23 panic(err)
24 }
25 defer trace.Stop()
26 urls := []string{"0.0.0.0:5000", "0.0.0.0:6000", "0.0.0.0:7000"}
27 wg := sync.WaitGroup{}
28 for _, url := range urls {
29 wg.Add(1)
30 go func() {
31 defer wg.Done()
32 mockSendToServer(url)
33 }()
34 }
35 wg.Wait()
36}
运行命令 go run main.go ，将在同级目录生成 trace.out 文件。此时，执行 go tool 命令。
1go tool trace trace.out
22020/08/15 16:35:58 Parsing trace...
32020/08/15 16:35:58 Splitting trace...
42020/08/15 16:35:58 Opening browser. Trace viewer is listening on http://127.0.0.1:61272
在 web 浏览器（推荐使用 Chrome）打开 http://127.0.0.1:61272
在这里，我们只关心两项指标。第一行 View trace（可视化整个程序的调度流程）和第二行 Groutine analysis。相信读者对 trace 和 pprof 的基本玩法都有了解，这里就不做过多介绍。后续小菜刀也会尽力出一些关于它们使用的详细文章。
进入 Goroutine analysis 项。
可以看到，程序一共有 5 个 goroutine，分别是三个 for 循环里启动的匿名 go func()、一个 trace.Start.func1 和 runtime.main。
进入 main.main.func1
这三个代表的就是 for 循环结构体里面启动的三个 goroutine。这里，请记住它们的编号 19、20、21。
此时，退回到 http://127.0.0.1:61272 页面，进入 View trace 项。
点击 G1（G1 代表的是 runtime.main）所在的绿色方框，得到如下信息
上图是重点！我们可以看到 G18、G19、G20、G21 都是通过 G1 衍生出来的。同时可以看到，G1 运行阻塞于第 35 行代码处，即 wg.Wait()。
但是，通过上图中 goroutine 的运行时序，此时 for 循环中的 3 个 goroutine 均还未成功启动运行（虽然已经在主 goroutine 即 main 中通过 go 关键字进行了 goroutine 调用声明）。
那么，到这里读者应该清楚上文中 bug 产生的原因了吧。
1for _, url := range urls {
2 wg.Add(1)
3 go func() {
4 defer wg.Done()
5 mockSendToServer(url)
6 }()
7}
8wg.Wait()
原因
当主 goroutine 中的 for 循环逻辑已经走完并阻塞于 wg.Wait（）一段时间后，go func 的 goroutine 才启动准备（准备资源，挂载 M 线程等）完毕。那么，此时三个 goroutine 中获取的 url 都是指向的最后一次 for 循环的 url，因此就造成了上文中的 bug。
**goroutine 的启动时间是多少
**
通过在小菜刀电脑上的多次运行观察，一次 goroutine 的启动准备时间在数十微秒左右。当然该值在不同的操作系统和硬件设备上肯定会存在一些差异。为此，小菜刀在程序以下部分做了些小改动，以做测试
1for i, url := range urls {
2 wg.Add(1)
3 go func() {
4 defer wg.Done()
5 mockSendToServer(url)
6 }()
7 if i == 1 {
8 //在读取url为"0.0.0.0:6000"时，睡50微秒
9 time.Sleep(time.Microsecond * 50)
10 }
11}
12wg.Wait()
程序多次运行会产生不同的结果
1 $ go run main.go
2server url: 0.0.0.0:6000
3server url: 0.0.0.0:7000
4server url: 0.0.0.0:6000
5
6 $ go run main.go
7server url: 0.0.0.0:6000
8server url: 0.0.0.0:6000
9server url: 0.0.0.0:7000
10
11 $ go run main.go
12server url: 0.0.0.0:6000
13server url: 0.0.0.0:7000
14server url: 0.0.0.0:7000
那么，我们就选取 6000、7000、7000 的结果来分析下当时 goroutine 的启动和调度情况。
如上，可以得知：由于在第二次 for 循环中让主 goroutine 睡了 50 微秒，使得首次被主 goroutine 调起的 go func（上图表现为 G20）已经得到了充足的时间来准备启动。但是首次调起的 go func，其获取 url 的时间片是在第二次循环的睡眠阶段，因此它得到的 url 是 "0.0.0.0:6000"，而其他两个 go func（G21 和 G19）最终运行时获取的值还是 "0.0.0.0:7000" 的 url。
之所以睡眠 50 微秒会造成不同的结果，是由于 goroutine 的启动时间并不固定，会存在一定范围的波动。
因此，解决上文的 bug 的方案应为如下
1for _, url := range urls {
2 wg.Add(1)
3 go func(url string) {
4 defer wg.Done()
5 mockSendToServer(url)
6 }(url)
7}
8wg.Wait()
将每次遍历的 url 所指向值，通过函数入参，作为数据资源赋予给 go func, 这样不管 goroutine 启动会有多耗时，其 url 已经作为 goroutine 的私有数据保存，后续运行就用上了正确的 url，那么，上文 bug 也相应解除。
后记
小菜刀在线上遇到该 bug 时，虽然已经知道通过 url 入参的方式进行修改，但当时没有过多思考，以为问题是出在了 for...range 的值拷贝上面。通过后续和同事的讨论与自己多次不同尝试之后，才意识到原来是 goroutine 的启动时间在捣鬼。
最后，希望读者们看完此文，不会再写出此 bug。
往期精彩推荐
Golang 技术分享
