哈哈，我好像發(fā)現(xiàn)了一個(gè)Go 的 Bug ？
從一次重構(gòu)說起
這事兒還得從一次重構(gòu)優(yōu)化說起。
最近在重構(gòu)一個(gè)路由功能，由于路由比較復(fù)雜，需求變化也多，于是想通過責(zé)任鏈模式來重構(gòu)，剛好這段時(shí)間也在 Sentinel-Go 中看到相關(guān)源碼。
用責(zé)任鏈模式，最大的好處是可以針對(duì)每次請(qǐng)求靈活地插拔路由能力，如：
這樣實(shí)現(xiàn)會(huì)在每次請(qǐng)求到來時(shí)去new 出整個(gè)責(zé)任鏈，可以預(yù)見對(duì)象會(huì)頻繁的創(chuàng)建、銷毀。
對(duì) Java 來說，對(duì)象池并不推薦，除非對(duì)象的創(chuàng)建特別費(fèi)力，像一個(gè)連接對(duì)象，否則線程之間的鎖競(jìng)爭(zhēng)絕對(duì)比直接分配內(nèi)存的消耗要多的多~
但 Go 不一樣，它內(nèi)置的 sync.Pool 配合調(diào)度模型（GMP）能夠剛好規(guī)避這種鎖競(jìng)爭(zhēng)。
大家知道 Go 的對(duì)象池很牛逼就行了，具體原理不是本文重點(diǎn)，也不是一兩句話能解釋的清楚，有機(jī)會(huì)再寫一篇文章詳細(xì)說道~
但理論歸理論，是騾子是馬，得拉出來遛遛才知道是不是真的牛逼~
Benchmark 超時(shí)！
測(cè)試這種性能，Benchmark 肯定是首選，于是我寫了兩個(gè)例子來對(duì)比，直接 New 對(duì)象和使用 sync.Pool 池化對(duì)象。
func?BenchmarkPooledObject(b?*testing.B)?{
?b.RunParallel(func(pb?*testing.PB)?{
??for?pb.Next()?{
???object?:=?pool.Get().(*MyObject)
???Consume(object)
???//?用完了放回對(duì)象池
???object.Reset()
???pool.Put(object)
??}
?})
}
func?BenchmarkNewObject(b?*testing.B)?{
?b.RunParallel(func(pb?*testing.PB)?{
??for?pb.Next()?{
???object?:=?&MyObject{
????Name:?"hello",
????Age:??2,
???}
???Consume(object)
??}
?})
}
當(dāng)時(shí)是這些測(cè)試參數(shù)
go?test?-bench=.?-cpu=4?-count=2?-benchtime=10s
跑出了如下結(jié)果，似乎還是直接 New 對(duì)象更快，這和理論不符合??！
BenchmarkPooledObject-4?????????1000000000???????????????6.25?ns/op
BenchmarkNewObject-4????????????1000000000???????????????0.374?ns/op
于是就想，是不是我測(cè)試的方法哪里不太對(duì)？
池化技術(shù)能減少對(duì)象的創(chuàng)建、銷毀的消耗，有很大一部分得益于減少 GC 次數(shù)，是不是我這只跑了10s，還沒開始 GC ？
于是我查了下，什么時(shí)候 Go 會(huì)觸發(fā) GC，得到了如下的答案：
主動(dòng)調(diào)用 runtime.GC來觸發(fā)被動(dòng)觸發(fā)，分為兩種： 超過2分鐘沒有觸發(fā)，則強(qiáng)制觸發(fā) GC 內(nèi)存增長(zhǎng)達(dá)到一定比例，觸發(fā) GC，比如初始化堆大小為4MB，當(dāng)增長(zhǎng) 25%時(shí)，即5MB 時(shí)觸發(fā)一次GC
顯然主動(dòng)觸發(fā)不合適，被動(dòng)觸發(fā)沒法確認(rèn)增長(zhǎng)比例，那只能依靠2分鐘強(qiáng)制觸發(fā) GC 來達(dá)到目的了，于是我把基礎(chǔ)測(cè)試的時(shí)間加長(zhǎng)，改成了 ?-benchtime=150s。
執(zhí)行后，就去泡了杯茶，上了個(gè)廁所...過了很久，終于執(zhí)行完了，結(jié)果卻是這樣的結(jié)局：
***?Test?killed?with?quit:?ran?too?long?(11m0s).
執(zhí)行失敗了，而且還執(zhí)行了11分鐘~
我搜索了下這個(gè)報(bào)錯(cuò)，網(wǎng)上說的是，Go 的單元測(cè)試和 Benchmark 都有超時(shí)時(shí)間，默認(rèn)是10分鐘，可以通過 -timeout 來修改。
但這不是重點(diǎn)，重點(diǎn)是為啥我設(shè)置了150s，卻執(zhí)行了11分鐘？
源碼之下沒有秘密
直覺告訴我這事不簡(jiǎn)單，要么是我錯(cuò)了，要么是 Go 錯(cuò)了~ 幸好 Go 是開源的，源碼之下沒有秘密。
通過 Debug 和代碼查閱后，先是找到了這段代碼
func?(b?*B)?runN(n?int)?{
?benchmarkLock.Lock()
?defer?benchmarkLock.Unlock()
?defer?b.runCleanup(normalPanic)
?//?注意看這里，幫我們GC了
?runtime.GC()
?b.raceErrors?=?-race.Errors()
?b.N?=?n
?b.parallelism?=?1
?//?重置計(jì)時(shí)器
?b.ResetTimer()
?//?開始計(jì)時(shí)
?b.StartTimer()
?//?執(zhí)行?benchmark?方法?
?b.benchFunc(b)
?//?停止計(jì)時(shí)
?b.StopTimer()
?b.previousN?=?n
?b.previousDuration?=?b.duration
?b.raceErrors?+=?race.Errors()
?if?b.raceErrors?>?0?{
??b.Errorf("race?detected?during?execution?of?benchmark")
?}
}
這段代碼是在執(zhí)行一次我們定義的 Benchmark 方法，n 就是傳入到我們定義方法參數(shù)的 *testing.B 結(jié)構(gòu)中的一個(gè)屬性。而且它計(jì)算的時(shí)間也非常合理，只計(jì)算了執(zhí)行我們定義方法的時(shí)間，也就是 -benchtime 的時(shí)間只是函數(shù)執(zhí)行的時(shí)間，Benchmark 框架的耗時(shí)不計(jì)算在內(nèi)。
更合理的是，框架在執(zhí)行方法前，還幫我們觸發(fā)了一次 GC，也就是說，只有我們的函數(shù)在執(zhí)行的時(shí)候產(chǎn)生的內(nèi)存垃圾才算到我們的 Benchmark 時(shí)間中，非常嚴(yán)謹(jǐn)。
但這跟我們的執(zhí)行失敗毫無關(guān)系~
但從一個(gè)側(cè)面來說，Benchmark 執(zhí)行的總時(shí)間一定是大于 -benchtime 設(shè)置的時(shí)間的。
真的是這樣嗎？我做了兩組實(shí)驗(yàn)，就打破了這個(gè)規(guī)律：
go?test?-bench=.?-cpu=4?-count=1?-benchtime=5s
?
BenchmarkPooledObject-4?????????793896368????????????????7.65?ns/op
BenchmarkNewObject-4????????????1000000000???????????????0.378?ns/op
PASS
ok??????all-in-one/go-in-one/samples/object_pool????????7.890s
go?test?-bench=.?-cpu=4?-count=1?-benchtime=10s
BenchmarkPooledObject-4?????????1000000000???????????????7.16?ns/op
BenchmarkNewObject-4????????????1000000000???????????????0.376?ns/op
PASS
ok??????all-in-one/go-in-one/samples/object_pool????????8.508s
第二組設(shè)置了執(zhí)行 10s，但總的測(cè)試時(shí)間只有8.508s，很奇怪，更奇怪的是測(cè)試結(jié)果的第二列執(zhí)行次數(shù)，他們居然都是 1000000000，這么巧嗎？
帶著疑問，找到了 Benchmark 的這段核心代碼：
func?(b?*B)?launch()?{
???...
?//?標(biāo)注①
?if?b.benchTime.n?>?0?{
??//?We?already?ran?a?single?iteration?in?run1.
??//?If?-benchtime=1x?was?requested,?use?that?result.
??if?b.benchTime.n?>?1?{
???b.runN(b.benchTime.n)
??}
?}?else?{
??d?:=?b.benchTime.d
???//?標(biāo)注②
??for?n?:=?int64(1);?!b.failed?&&?b.duration?1e9;?{
???last?:=?n
???goalns?:=?d.Nanoseconds()
???prevIters?:=?int64(b.N)
???prevns?:=?b.duration.Nanoseconds()
???if?prevns?<=?0?{
????prevns?=?1
???}
????//?標(biāo)注③
???n?=?goalns?*?prevIters?/?prevns
???//?Run?more?iterations?than?we?think?we'll?need?(1.2x).
???//?標(biāo)注④
???n?+=?n?/?5
???//?Don't?grow?too?fast?in?case?we?had?timing?errors?previously.
???//?標(biāo)注⑤
???n?=?min(n,?100*last)
???//?Be?sure?to?run?at?least?one?more?than?last?time.
???//?標(biāo)注⑥
???n?=?max(n,?last+1)
???//?Don't?run?more?than?1e9?times.?(This?also?keeps?n?in?int?range?on?32?bit?platforms.)
???//?標(biāo)注⑦
???n?=?min(n,?1e9)
???//?標(biāo)注⑧
???b.runN(int(n))
??}
?}
?b.result?=?BenchmarkResult{b.N,?b.duration,?b.bytes,?b.netAllocs,?b.netBytes,?b.extra}
}
核心都標(biāo)了序號(hào)，這里來解釋下：
標(biāo)注①：Go 的 Benchmark 執(zhí)行兩種傳參，執(zhí)行次數(shù)和執(zhí)行時(shí)間限制，我用的是執(zhí)行時(shí)間，也可以用 -benchtime=1000x來表示需要測(cè)試1000次。
標(biāo)注②：這里是當(dāng)設(shè)置了執(zhí)行時(shí)間限制時(shí)，判斷時(shí)間是否足夠的條件，可以看到除了時(shí)間的判斷外，還有 n < 1e9 的限制，也就是最多執(zhí)行次數(shù)是 1e9，也就是 1000000000，這解釋了上面的一個(gè)困惑，為啥執(zhí)行時(shí)間還比設(shè)置的 benchtime 小。因?yàn)?Go 限制了最大執(zhí)行次數(shù)為 1e9，并不是設(shè)置多少就是多少，還有個(gè)上限。
標(biāo)注③到⑧:
Go 是如何知道 n 取多少時(shí)，時(shí)間剛好符合我們?cè)O(shè)置的 benchtime？答案是試探！
n 從1 開始試探，執(zhí)行1次后，根據(jù)執(zhí)行時(shí)間來估算 n。n = goalns * prevIters / prevns，這就是估算公式，goalns 是設(shè)置的執(zhí)行時(shí)間（單位納秒），prevIters 是上次執(zhí)行次數(shù)，prevns 是上一次執(zhí)行時(shí)間（納秒）
根據(jù)上次執(zhí)行的時(shí)間和目標(biāo)設(shè)定的執(zhí)行總時(shí)間，計(jì)算出需要執(zhí)行的次數(shù)，大概是這樣吧：
目標(biāo)執(zhí)行次數(shù) = 執(zhí)行目標(biāo)時(shí)間 / (上次執(zhí)行時(shí)間 / 上次執(zhí)行次數(shù))
化簡(jiǎn)下得到：
目標(biāo)執(zhí)行次數(shù) = 執(zhí)行目標(biāo)時(shí)間 * 上次執(zhí)行次數(shù) / 上次執(zhí)行時(shí)間，這不就是上面那個(gè)公式~
目標(biāo)執(zhí)行次數(shù) n 的計(jì)算，源碼中還做了一些其他處理：
標(biāo)注④：讓實(shí)際執(zhí)行次數(shù)大概是目標(biāo)執(zhí)行次數(shù)的 1.2倍，萬一達(dá)不到目標(biāo)時(shí)間不是有點(diǎn)尷尬？索性多跑一會(huì)標(biāo)注⑤：也不能讓 n 增長(zhǎng)的太快了，設(shè)置個(gè)最大增長(zhǎng)幅度為100倍，當(dāng) n 增長(zhǎng)太快時(shí)，被測(cè)試方法一定是執(zhí)行時(shí)間很短，誤差可能較大，緩慢增長(zhǎng)好測(cè)出真實(shí)的水平 標(biāo)注⑥：n 不能原地踏步，怎么也得+1 標(biāo)注⑦：n 得設(shè)置個(gè) 1e9 的上限，這是為了在32位系統(tǒng)上不要溢出
Go Benchmark 的執(zhí)行原理大致摸清了，但我們要的答案還未浮出水面。
接著我對(duì) Benchmark 進(jìn)行了斷點(diǎn)調(diào)試。
首先是 -benchtime=10s
發(fā)現(xiàn) n 的試探增長(zhǎng)是 1，100，10000，1000000，100000000，1000000000，最終 n 是 1000000000
這說明我們的執(zhí)行方法耗時(shí)很短，執(zhí)行次數(shù)達(dá)到了上限。
再看-benchtime=150s，開始還挺正常：
n 增長(zhǎng)是 1，100，10000，1000000，100000000，但后一個(gè)出現(xiàn)了問題：
n 居然變成了負(fù)數(shù)！顯然這是溢出了。
n = goalns * prevIters / prevns 這個(gè)公式，在目標(biāo)執(zhí)行時(shí)間（goalns）很大，測(cè)試方法執(zhí)行時(shí)間（prevns）很短時(shí)，會(huì)導(dǎo)致 n 溢出！
溢出有什么后果呢？
后面的 n = min(n, 100*last) 永遠(yuǎn)等于 100000000 了，但還有 n = max(n, last+1) 保證，所以 n 還是在增加，不過很慢，每次都只 +1，所以后續(xù)試探的 n 序列為 100000001，100000002，100000003....
這就導(dǎo)致了 n 很難達(dá)到 1e9 的上限，而且總的執(zhí)行耗時(shí)也很難達(dá)到設(shè)定的預(yù)期時(shí)間，所以測(cè)試程序會(huì)一直跑~直到超時(shí)！
這大概是一個(gè)Bug吧？
寫這段 Benchamrk 邏輯的作者加入了這個(gè) 1e9 的執(zhí)行次數(shù)上限，考慮了溢出，但沒有考慮 n 在計(jì)算過程中的溢出情況。
我覺得這應(yīng)該是一個(gè) Bug，但不能完全確定。
網(wǎng)上沒有找到相關(guān)的 Bug 報(bào)告，于是去給 Go 官方提了 issue 和相應(yīng)的修復(fù)代碼，由于 Go 的開發(fā)流程比較復(fù)雜和漫長(zhǎng)，所以在本文發(fā)表時(shí)，官方并沒有明確表明這是 Bug 還是其他。
明哥注：以上為原文，經(jīng)與原作者確認(rèn)，該 Bug 已被官方認(rèn)定為 Bug 。
? ?
???