testing: inconsistent benchmark measurements when interrupts timer

[changkun]

What version of Go are you using (go version)?

$ go version
go version devel +8266570ba7 Fri Sep 25 19:10:05 2020 +0000 darwin/amd64

Does this issue reproduce with the latest release?

Yes. 1.15.2

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/changkun/Library/Caches/go-build"
GOENV="/Users/changkun/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/changkun/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/changkun/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/changkun/dev/godev/go-gerrit"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/changkun/dev/godev/go-gerrit/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/changkun/dev/godev/tests/issue_27217/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/jd/vym7tt9s2_379d4ccjcj1xrw0000gn/T/go-build781391859=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

// main_test.go
func BenchmarkAtomic(b *testing.B) {
	var v int32
	atomic.StoreInt32(&v, 0)
	b.Run("with-timer", func(b *testing.B) {
		for i := 0; i < b.N; i++ {
			b.StopTimer()
			b.StartTimer()
			atomic.AddInt32(&v, 1)
		}
	})
	atomic.StoreInt32(&v, 0)
	b.Run("w/o-timer", func(b *testing.B) {
		for i := 0; i < b.N; i++ {
			atomic.AddInt32(&v, 1)
		}
	})
}

Run benchmarks with the following command:

$ go test -run=none -bench=. -benchtime=1000x -count=20 | tee b.txt && benchstat b.txt

What did you expect to see?

Similar results for the with-timer and w/o-timer benchmarks

What did you see instead?

name                 time/op
Atomic/with-timer-6  63.0ns ±12%
Atomic/w/o-timer-6   4.90ns ± 1%

[andybons]

@rsc @ianlancetaylor @dvyukov @aclements @jayconrod @matloob @bcmills

[changkun]

To whom it may concern:

The issue is caused by the overhead of calling time.Now() in StopTimer/StartTimer. The actual measured time of a target code equals the execution time of the target code plus the overhead of calling time.Now(). One can verify this using pprof.

Assume the target code consumes in T ns, and the overhead of calling time.Now() is t ns. If the target code runs N times, the total measured time is T*N+t, then the average of a single iteration of the target code is T+t/N. Thus, the systematic measurement error becomes t/N. Therefore, with a higher N, a less systematic error is obtained.

Another approach to address this is to measure the overhead of a calling time.Now(), then subtract the overhead from the benchmark result.

Since this issue can only impact microbenchmarks, people who do such a test tend to know what they are doing. Close because no further action to take.