不要忽略goroutine的启动时间

痛定思痛。 2022-09-03 09:26 103阅读 0赞

小菜刀的项目中需要将数据推给多个服务器，大致如下

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。

![e8224a4137ca4af98d630e4e9ccfdb68.gif][]

**原因分析**

在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*

![1ac3e1cd5fd2206bf467505d7e8c8288.png][]

在这里，我们只关心两项指标。第一行View trace（可视化整个程序的调度流程）和第二行Groutine analysis。相信读者对trace和pprof的基本玩法都有了解，这里就不做过多介绍。后续小菜刀也会尽力出一些关于它们使用的详细文章。

进入Goroutine analysis项。

![c3fb3c4467daf642c4c61f29fb97c6e4.png][]

可以看到，程序一共有5个goroutine，分别是三个for循环里启动的匿名go func()、一个trace.Start.func1和runtime.main。

进入main.main.func1

![688d21378eb898a1ab2e5af1a1efbd1b.png][]

这三个代表的就是for循环结构体里面启动的三个goroutine。这里，请记住它们的编号19、20、21。

此时，退回到*http://127.0.0.1:61272*页面，进入View trace项。

![07b42c95ba3bf95c20f70a390e59b828.png][]

![02fb468e6de6cf71f10f178606c7362c.png][]

![8218436c160605f2fad402d305026c44.png][]

点击G1（G1代表的是runtime.main）所在的绿色方框，得到如下信息

![e70baaf01bbed5b2ac820016210cfca0.png][]

上图是重点！我们可以看到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。

![50d86e7bd41dc8251c4a8d879361fa53.gif][]

**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的启动和调度情况。

![085f5a5ecb3d084b4c766cdc29d66e47.png][]

如上，可以得知：由于在第二次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也相应解除。

![6e96302a0f6ae9677f143a7e44072a8d.gif][]

**后记**

小菜刀在线上遇到该bug时，虽然已经知道通过url入参的方式进行修改，但当时没有过多思考，以为问题是出在了for...range的值拷贝上面。通过后续和同事的讨论与自己多次不同尝试之后，才意识到原来是goroutine的启动时间在捣鬼。

最后，希望读者们看完此文，不会再写出此bug。

**往期精彩推荐**

*  [goroutine的退出与泄露][goroutine]
 *  [一次错误吞并的教训][Link 1]  
    
 *  [Go工具之generate][Go_generate]  
    
 *  [no copy机制][no copy]
 *  [高并发系统之限流技术][Link 2]  
    
 *  [信号处理与Go程序的优雅退出][Go]

**Golang技术分享**

长按识别二维码关注我们

更多golang学习资料

回复关键词**1024**

![73b51006ec412de0f3f8a03d1f2e644e.png][]

[e8224a4137ca4af98d630e4e9ccfdb68.gif]: /images/20220829/f8ac40c6d618446583be98774e722a94.png
[1ac3e1cd5fd2206bf467505d7e8c8288.png]: /images/20220829/c585abd2558d4628a78bef8e385cf0d2.png
[c3fb3c4467daf642c4c61f29fb97c6e4.png]: /images/20220829/c8a6957e734b441a806b1e6c3f3d3d7b.png
[688d21378eb898a1ab2e5af1a1efbd1b.png]: /images/20220829/302fd2b6a07d48fa9dd0a9d71122ac92.png
[07b42c95ba3bf95c20f70a390e59b828.png]: /images/20220829/2a7f58da59824166967f188b599e4e4a.png
[02fb468e6de6cf71f10f178606c7362c.png]: /images/20220829/e4bb6469a98a454f8245eae704cf0c34.png
[8218436c160605f2fad402d305026c44.png]: /images/20220829/fe32f0f29af849958e5b852fa5fce1f3.png
[e70baaf01bbed5b2ac820016210cfca0.png]: /images/20220829/1472e417fdb047dc971fc6262b65586a.png
[50d86e7bd41dc8251c4a8d879361fa53.gif]: /images/20220829/25ec4014dcec4c8e9ffa715dc3e139b7.png
[085f5a5ecb3d084b4c766cdc29d66e47.png]: /images/20220829/6d6a272e684f4f0ab92e49b7c58f0466.png
[6e96302a0f6ae9677f143a7e44072a8d.gif]: /images/20220829/cf572ecf22294d7e99f5e734dfbc80a8.png
[goroutine]: http://mp.weixin.qq.com/s?__biz=MzIwNTA4MDAwMQ%3D%3D&chksm=97371665a0409f73561af432cdbf2f21338c95ac486da491bd5e1d4fc432b51509bdb45f0c16&idx=1&mid=2247484107&scene=21&sn=a126a0cc7b0442589d83df29089b10b8#wechat_redirect
[Link 1]: http://mp.weixin.qq.com/s?__biz=MzIwNTA4MDAwMQ%3D%3D&chksm=9737166fa0409f793dabcd8dd8ca5c85c1e89a8a7f99e36f5a48ec3d40d434cf1199a6ba6297&idx=1&mid=2247484097&scene=21&sn=5470f4107bb258e105d8ef33000188ae#wechat_redirect
[Go_generate]: http://mp.weixin.qq.com/s?__biz=MzIwNTA4MDAwMQ%3D%3D&chksm=9737161da0409f0b50f62b48c5b83d61d9754a43a80e83797df459afb2adada2176a0e04c2eb&idx=1&mid=2247484083&scene=21&sn=7571b866c11930c48830060f7a002b82#wechat_redirect
[no copy]: http://mp.weixin.qq.com/s?__biz=MzIwNTA4MDAwMQ%3D%3D&chksm=973716c7a0409fd1440d74edfb8949d2c3f2d49984fdae08fd1ce0581ea7705cbf6513a3bcdf&idx=1&mid=2247484009&scene=21&sn=1dc6689045b8a1d04cb4d6dd67a6b66b#wechat_redirect
[Link 2]: http://mp.weixin.qq.com/s?__biz=MzIwNTA4MDAwMQ%3D%3D&chksm=9737151aa0409c0cf8f39ce03c2ce90c7d3da029249ca80bcf06ca9f9b45cda45cd2079387bc&idx=1&mid=2247483828&scene=21&sn=88bcacc010a57311739f0cbc4f8920d8#wechat_redirect
[Go]: http://mp.weixin.qq.com/s?__biz=MzIwNTA4MDAwMQ%3D%3D&chksm=97371575a0409c635e4a66a4d23b37bc90b78504ad733055ebb1d0256f7b6cb1a26ae3ecffec&idx=1&mid=2247483867&scene=21&sn=5672d9bfabd66794b139f676d71ca5ca#wechat_redirect
[73b51006ec412de0f3f8a03d1f2e644e.png]: /images/20220829/7cf47dae0626470ca271449ecf337048.png