不要忽略 goroutine 的啟動(dòng)時(shí)間

 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}

請(qǐng)讀者停來(lái)下思考一下，以上代碼會(huì)得到什么樣的輸出。

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

這個(gè)結(jié)果，是不是和你想的一樣呢。那么，問(wèn)題出在了哪里？為什么從for循環(huán)中傳遞的url變得相同了，且為數(shù)組中的最后一項(xiàng)url。

原因分析

在Go中提供了非常好的程序分析工具，trace和pprof。trace側(cè)重于分析goroutine的調(diào)度，pprof則側(cè)重于程序的運(yùn)行性能。為了更好地排查上述bug產(chǎn)生的原因，代碼中新增了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}

運(yùn)行命令go?run?main.go? ，將在同級(jí)目錄生成trace.out文件。此時(shí)，執(zhí)行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

在這里，我們只關(guān)心兩項(xiàng)指標(biāo)。第一行View trace（可視化整個(gè)程序的調(diào)度流程）和第二行Groutine analysis。相信讀者對(duì)trace和pprof的基本玩法都有了解，這里就不做過(guò)多介紹。后續(xù)小菜刀也會(huì)盡力出一些關(guān)于它們使用的詳細(xì)文章。

進(jìn)入Goroutine analysis項(xiàng)。

可以看到，程序一共有5個(gè)goroutine，分別是三個(gè)for循環(huán)里啟動(dòng)的匿名go func()、一個(gè)trace.Start.func1和runtime.main。

進(jìn)入main.main.func1

這三個(gè)代表的就是for循環(huán)結(jié)構(gòu)體里面啟動(dòng)的三個(gè)goroutine。這里，請(qǐng)記住它們的編號(hào)19、20、21。

此時(shí)，退回到http://127.0.0.1:61272頁(yè)面，進(jìn)入View trace項(xiàng)。

點(diǎn)擊G1（G1代表的是runtime.main）所在的綠色方框，得到如下信息

上圖是重點(diǎn)！我們可以看到G18、G19、G20、G21都是通過(guò)G1衍生出來(lái)的。同時(shí)可以看到，G1運(yùn)行阻塞于第35行代碼處，即wg.Wait()。

但是，通過(guò)上圖中g(shù)oroutine的運(yùn)行時(shí)序，此時(shí)for循環(huán)中的3個(gè)goroutine均還未成功啟動(dòng)運(yùn)行（雖然已經(jīng)在主goroutine即main中通過(guò)go關(guān)鍵字進(jìn)行了goroutine調(diào)用聲明）。

那么，到這里讀者應(yīng)該清楚上文中bug產(chǎn)生的原因了吧。

1for?_,?url?:=?range?urls?{
2????wg.Add(1)
3????go?func()?{
4????????defer?wg.Done()
5????????mockSendToServer(url)
6????}()
7}
8wg.Wait()

原因

當(dāng)主goroutine中的for循環(huán)邏輯已經(jīng)走完并阻塞于wg.Wait（）一段時(shí)間后，go func的goroutine才啟動(dòng)準(zhǔn)備（準(zhǔn)備資源，掛載M線程等）完畢。那么，此時(shí)三個(gè)goroutine中獲取的url都是指向的最后一次for循環(huán)的url，因此就造成了上文中的bug。

goroutine的啟動(dòng)時(shí)間是多少

通過(guò)在小菜刀電腦上的多次運(yùn)行觀察，一次goroutine的啟動(dòng)準(zhǔn)備時(shí)間在數(shù)十微秒左右。當(dāng)然該值在不同的操作系統(tǒng)和硬件設(shè)備上肯定會(huì)存在一些差異。為此，小菜刀在程序以下部分做了些小改動(dòng)，以做測(cè)試

 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"時(shí)，睡50微秒
 9????????time.Sleep(time.Microsecond?*?50)
10????}
11}
12wg.Wait()

程序多次運(yùn)行會(huì)產(chǎn)生不同的結(jié)果

 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的結(jié)果來(lái)分析下當(dāng)時(shí)goroutine的啟動(dòng)和調(diào)度情況。

如上，可以得知：由于在第二次for循環(huán)中讓主goroutine睡了50微秒，使得首次被主goroutine調(diào)起的go func（上圖表現(xiàn)為G20）已經(jīng)得到了充足的時(shí)間來(lái)準(zhǔn)備啟動(dòng)。但是首次調(diào)起的go func，其獲取url的時(shí)間片是在第二次循環(huán)的睡眠階段，因此它得到的url是"0.0.0.0:6000"，而其他兩個(gè)go func（G21和G19）最終運(yùn)行時(shí)獲取的值還是"0.0.0.0:7000"的url。

之所以睡眠50微秒會(huì)造成不同的結(jié)果，是由于goroutine的啟動(dòng)時(shí)間并不固定，會(huì)存在一定范圍的波動(dòng)。

因此，解決上文的bug的方案應(yīng)為如下

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所指向值，通過(guò)函數(shù)入?yún)ⅲ鳛閿?shù)據(jù)資源賦予給go func,這樣不管goroutine啟動(dòng)會(huì)有多耗時(shí)，其url已經(jīng)作為goroutine的私有數(shù)據(jù)保存，后續(xù)運(yùn)行就用上了正確的url，那么，上文bug也相應(yīng)解除。

后記

小菜刀在線上遇到該bug時(shí)，雖然已經(jīng)知道通過(guò)url入?yún)⒌姆绞竭M(jìn)行修改，但當(dāng)時(shí)沒(méi)有過(guò)多思考，以為問(wèn)題是出在了for...range的值拷貝上面。通過(guò)后續(xù)和同事的討論與自己多次不同嘗試之后，才意識(shí)到原來(lái)是goroutine的啟動(dòng)時(shí)間在搗鬼。

最后，希望讀者們看完此文，不會(huì)再寫出此bug。