從一次重構說起
這事兒還得從一次重構優化說起。
最近在重構一個路由功能，由於路由比較複雜，需求變化也多，於是想通過責任鏈模式來重構，剛好這段時間也在 Sentinel-Go 中看到相關原始碼。
用責任鏈模式，最大的好處是可以針對每次請求靈活地插拔路由能力，如：
這樣實現會在每次請求到來時去 new 出整個責任鏈，可以預見物件會頻繁的建立、銷燬。
對 Java 來說，物件池並不推薦，除非物件的建立特別費力，像一個連線物件，否則執行緒之間的鎖競爭絕對比直接分配記憶體的消耗要多的多~
但 Go 不一樣，它內建的 sync.Pool 配合排程模型（GMP）能夠剛好規避這種鎖競爭。
大家知道 Go 的物件池很牛逼就行了，具體原理不是本文重點，也不是一兩句話能解釋的清楚，有機會再寫一篇文章詳細說道~
但理論歸理論，是騾子是馬，得拉出來遛遛才知道是不是真的牛逼~
Benchmark 超時！
測試這種效能，Benchmark 肯定是首選，於是我寫了個兩個例子來對比，直接 New 物件和使用 sync.Pool 池化物件。
func BenchmarkPooledObject(b *testing.B) {
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
object := pool.Get().(*MyObject)
Consume(object)
// 用完了放回物件池
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)
}
})
}
當時是這些測試引數
go test -bench=. -cpu=4 -count=2 -benchtime=10s
跑出瞭如下結果，似乎還是直接 New 物件更快，這和理論不符合啊！
BenchmarkPooledObject-4 1000000000 6.25 ns/op
BenchmarkNewObject-4 1000000000 0.374 ns/op
於是就想，是不是我測試的方法哪裡不太對？
池化技術能減少物件的建立、銷燬的消耗，有很大一部分得益於減少 GC 次數，是不是我這隻跑了10s，還沒開始 GC ？
於是我查了下，什麼時候 Go 會觸發 GC，得到了如下的答案：
- 主動呼叫
runtime.GC來觸發 - 被動觸發，分為兩種：
- 超過2分鐘沒有觸發，則強制觸發 GC
- 記憶體增長達到一定比例，觸發 GC，比如初始化堆大小為4MB，當增長 25%時，即5MB 時觸發一次GC
顯然主動觸發不合適，被動觸發沒法確認增長比例，那隻能依靠2分鐘強制觸發 GC 來達到目的了，於是我把基礎測試的時間加長，改成了 -benchtime=150s。
執行後，就去泡了杯茶，上了個廁所...過了很久，終於執行完了，結果卻是這樣的結局：
*** Test killed with quit: ran too long (11m0s).
執行失敗了，而且還執行了11分鐘~
我搜尋了下這個報錯，網上說的是，Go 的單元測試和 Benchmark 都有超時時間，預設是10分鐘，可以通過 -timeout 來修改。
但這不是重點，重點是為啥我設定了150s，卻執行了11分鐘？
原始碼之下沒有祕密
直覺告訴我這事不簡單，要麼是我錯了，要麼是 Go 錯了~ 幸好 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
// 重置計時器
b.ResetTimer()
// 開始計時
b.StartTimer()
// 執行 benchmark 方法
b.benchFunc(b)
// 停止計時
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")
}
}
這段程式碼是在執行一次我們定義的 Benchmark 方法，n 就是傳入到我們定義方法引數的 *testing.B 結構中的一個屬性。
而且它計算的時間也非常合理，只計算了執行我們定義方法的時間，也就是 -benchtime 的時間只是函式執行的時間，Benchmark 框架的耗時不計算在內。
更合理的是，框架在執行方法前，還幫我們觸發了一次 GC，也就是說，只有我們的函式在執行的時候產生的記憶體垃圾才算到我們的 Benchmark 時間中，非常嚴謹。
但這跟我們的執行失敗毫無關係~
但從一個側面來說，Benchmark 執行的總時間一定是大於 -benchtime 設定的時間的。
真的是這樣嗎？我做了兩組實驗，就打破了這個規律：
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
第二組設定了執行 10s，但總的測試時間只有8.508s，很奇怪，更奇怪的是測試結果的第二列執行次數，他們居然都是 1000000000，這麼巧嗎？
帶著疑問，找到了 Benchmark 的這段核心程式碼：
func (b *B) launch() {
...
// 標註①
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
// 標註②
for n := int64(1); !b.failed && b.duration < d && n < 1e9; {
last := n
goalns := d.Nanoseconds()
prevIters := int64(b.N)
prevns := b.duration.Nanoseconds()
if prevns <= 0 {
prevns = 1
}
// 標註③
n = goalns * prevIters / prevns
// Run more iterations than we think we'll need (1.2x).
// 標註④
n += n / 5
// Don't grow too fast in case we had timing errors previously.
// 標註⑤
n = min(n, 100*last)
// Be sure to run at least one more than last time.
// 標註⑥
n = max(n, last+1)
// Don't run more than 1e9 times. (This also keeps n in int range on 32 bit platforms.)
// 標註⑦
n = min(n, 1e9)
// 標註⑧
b.runN(int(n))
}
}
b.result = BenchmarkResult{b.N, b.duration, b.bytes, b.netAllocs, b.netBytes, b.extra}
}
核心都標了序號，這裡來解釋下：
標註①：Go 的 Benchmark 執行兩種傳參，執行次數和執行時間限制，我用的是執行時間，也可以用 -benchtime=1000x來表示需要測試1000次。
標註②：這裡是當設定了執行時間限制時，判斷時間是否足夠的條件，可以看到除了時間的判斷外，還有 n < 1e9 的限制，也就是最多執行次數是 1e9，也就是 1000000000，這解釋了上面的一個困惑，為啥執行時間還比設定的 benchtime 小。因為 Go 限制了最大執行次數為 1e9，並不是設定多少就是多少，還有個上限。
標註③到⑧:
Go 是如何知道 n 取多少時，時間剛好符合我們設定的 benchtime？答案是試探！
n 從1 開始試探，執行1次後，根據執行時間來估算 n。n = goalns * prevIters / prevns，這就是估算公式，goalns 是設定的執行時間（單位納秒），prevIters 是上次執行次數，prevns 是上一次執行時間（納秒）
根據上次執行的時間和目標設定的執行總時間，計算出需要執行的次數，大概是這樣吧：
目標執行次數 = 執行目標時間 / (上次執行時間 / 上次執行次數)
化簡下得到：
目標執行次數 = 執行目標時間 * 上次執行次數 / 上次執行時間，這不就是上面那個公式~
目標執行次數 n 的計算，原始碼中還做了一些其他處理：
- 標註④：讓實際執行次數大概是目標執行次數的
1.2倍，萬一達不到目標時間不是有點尷尬？索性多跑一會 - 標註⑤：也不能讓 n 增長的太快了，設定個最大增長幅度為100倍，當 n 增長太快時，被測試方法一定是執行時間很短，誤差可能較大，緩慢增長好測出真實的水平
- 標註⑥：n 不能原地踏步，怎麼也得+1
- 標註⑦：n 得設定個 1e9 的上限，這是為了在32位系統上不要溢位
Go Benchmark 的執行原理大致摸清了，但我們要的答案還未浮出水面。
接著我對 Benchmark 進行了斷點除錯。
首先是 -benchtime=10s
發現 n 的試探增長是 1，100，10000，1000000，100000000，1000000000，最終 n 是 1000000000
這說明我們的執行方法耗時很短，執行次數達到了上限。
再看-benchtime=150s，開始還挺正常：
n 增長是 1，100，10000，1000000，100000000，但後一個出現了問題：
n 居然變成了負數！顯然這是溢位了。
n = goalns * prevIters / prevns 這個公式，在目標執行時間（goalns）很大，測試方法執行時間（prevns）很短時，會導致 n 溢位！
溢位有什麼後果呢？
後面的 n = min(n, 100*last) 就是負數了，但還有 n = max(n, last+1) 保證，所以 n 還是在增加，不過很慢，每次都只 +1，所以後續試探的 n 序列為 100000001，100000002，100000003....
這就導致了 n 很難達到 1e9 的上限，而且總的執行耗時也很難達到設定的預期時間，所以測試程式會一直跑~直到超時！
這大概是一個Bug吧？
寫這段 Benchamrk 邏輯的作者加入了這個 1e9 的執行次數上限，考慮了溢位，但沒有考慮 n 在計算過程中的溢位情況。
我覺得這應該是一個 Bug，但不能完全確定。
網上沒有找到相關的 Bug 報告，於是去給 Go 官方提了 issue 和相應的修復程式碼，由於 Go 的開發流程比較複雜和漫長，所以在本文發表時，官方並沒有明確表明這是 Bug 還是其他。
如果後續官方有回覆或其他變故，我再來告訴大家~
搜尋關注微信公眾號"捉蟲大師"，後端技術分享，架構設計、效能優化、原始碼閱讀、問題排查、踩坑實踐。