Navigation Menu

Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

testing: inconsistent benchmark measurements when interrupts timer #41641

Closed
changkun opened this issue Sep 26, 2020 · 2 comments
Closed

testing: inconsistent benchmark measurements when interrupts timer #41641

changkun opened this issue Sep 26, 2020 · 2 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Unplanned

Comments

@changkun
Copy link
Member

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
Copy link
Member

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

@andybons andybons added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Sep 29, 2020
@andybons andybons added this to the Unplanned milestone Sep 29, 2020
@changkun
Copy link
Member Author

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.

@golang golang locked and limited conversation to collaborators Sep 30, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Unplanned
Development

No branches or pull requests
3 participants
@andybons @changkun @gopherbot