Go语言Benchmark RunParallel中fmt.Println多次执行的原因探究

问题背景 #

我编写了如下Go语言基准测试代码：

func BenchmarkParallel(b *testing.B) {
    var mu sync.Mutex
    var cnt int
    b.ResetTimer()
    b.SetParallelism(100)

    fmt.Println("cnt", cnt)
    b.RunParallel(func(pb *testing.PB) {
        mu.Lock()
        defer mu.Unlock()
        cnt++
        for pb.Next() {
            time.Sleep(time.Nanosecond)
            // time.Sleep(time.Second)
        }
    })
    fmt.Println("cnt", cnt)
}

执行命令：

$ go test -bench BenchmarkParallel -benchmem -test.count=1

得到输出：

cnt 0
cnt 800
BenchmarkParallel-8     cnt 0
cnt 800
cnt 0
cnt 800
cnt 0
cnt 800
cnt 0
cnt 800
 3987668               320.3 ns/op             0 B/op          0 allocs/op
PASS

发现fmt.Println执行了多次，但把time.Sleep(time.Nanosecond)改为time.Sleep(time.Second)后，cnt仅输出一次。预期fmt.Println只执行一次，请问这是什么原因？

原因解析 #

这是Go基准测试框架的预热（warm-up）机制导致的：

• 基准测试的预热逻辑：Go的testing包在正式执行基准测试前，会自动进行多次快速预热运行，目的是计算出合适的迭代次数，让测试总时长尽量接近1秒。每次预热都会完整执行你的BenchmarkParallel函数，因此函数开头和结尾的fmt.Println会被重复调用。
• 两种Sleep场景的差异：
  • 当使用time.Sleep(time.Nanosecond)时，单次迭代耗时极短，框架需要多次预热来调整迭代次数，所以会出现多组cnt输出。
  • 当换成time.Sleep(time.Second)时，单次迭代耗时极长，框架仅需少量迭代就能满足测试时长要求，预热阶段只执行一次，因此fmt.Println仅输出一次。
• 避免干扰的方法：如果不想让预热阶段的输出干扰结果，可将fmt.Println这类调试代码移到b.ResetTimer()之前，或者用b.Log替代fmt.Println——b.Log仅在测试失败或使用-v参数时才会输出，不会影响基准测试的正常输出。

内容的提问来源于stack exchange，提问作者ksCaesar