testing: strange benchmark results with RunParallel and -benchtime

[RaduBerinde]

Go version

go version go1.23.6 darwin/arm64

Output of go env in your module/workspace:

GO111MODULE='on'
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/radu/Library/Caches/go-build'
GOENV='/Users/radu/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/radu/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/radu/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/Users/radu/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.6.darwin-arm64'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/Users/radu/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.6.darwin-arm64/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.23.6'
GODEBUG=''
GOTELEMETRY='local'
GOTELEMETRYDIR='/Users/radu/Library/Application Support/go/telemetry'
GCCGO='gccgo'
GOARM64='v8.0'
AR='ar'
CC='clang'
CXX='clang++'
CGO_ENABLED='1'
GOMOD='/Users/radu/go/src/github.com/cockroachdb/pebble/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/x0/5yrxw_4s271g705vjscld23c0000gq/T/go-build4216578675=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

func BenchmarkFoo(b *testing.B) {
	b.RunParallel(func(pb *testing.PB) {
		n := 0
		for pb.Next() {
			n++
		}
		fmt.Fprintf(io.Discard, " %d\n", n)
	})
}

What did you see happen?

go test -bench BenchmarkFoo -run - ./internal/cache --count 1
goos: darwin
goarch: arm64
pkg: github.com/cockroachdb/pebble/internal/cache
cpu: Apple M1 Pro
BenchmarkFoo-10         1000000000               0.08839 ns/op
PASS
ok      github.com/cockroachdb/pebble/internal/cache    0.351s


go test -bench BenchmarkFoo -run - ./internal/cache --count 1 --benchtime=100000000x
goos: darwin
goarch: arm64
pkg: github.com/cockroachdb/pebble/internal/cache
cpu: Apple M1 Pro
BenchmarkFoo-10         100000000               73.14 ns/op
PASS
ok      github.com/cockroachdb/pebble/internal/cache    7.552s

What did you expect to see?

I expected the second variant to yield a similar result. 73ns per operation cannot be right.

[RaduBerinde]

@nvanbenschoten points out that the grain calculation is suspicious for this case:

go/src/testing/benchmark.go

Lines 867 to 881 in 0312e31

	// Calculate grain size as number of iterations that take ~100µs.
	// 100µs is enough to amortize the overhead and provide sufficient
	// dynamic load balancing.
	grain := uint64(0)
	if b.previousN > 0 && b.previousDuration > 0 {
	grain = 1e5 * uint64(b.previousN) / uint64(b.previousDuration)
	}
	if grain < 1 {
	grain = 1
	}
	// We expect the inner loop and function call to take at least 10ns,
	// so do not do more than 100µs/10ns=1e4 iterations.
	if grain > 1e4 {
	grain = 1e4
	}

[RaduBerinde]

Perhaps setting a lower bound like b.N / numProcs / 100 for the grain size would be sufficient.

[gabyhelp]

Related Issues

• testing: Benchmark, impossibly low ns/op #69417 (closed)
• testing: run first benchmark with last value from -cpu list GOMAXPROCS value #49980
• testing: benchmark cleanup causes inconsistent and slower benchmark time #38314 (closed)
• Benchmark results vastly different when Tests are skipped with -run=XXX #42696 (closed)
• testing: Inconsistent benchmark data when  GOMAXPROCS=1 #31599
• cmd/go: go run and go tool are slower than directly executing cached binary #71733
• runtime: huge performance drops in a timer application #35395 (closed)
• runtime: go 1.10beta2 Benchmarks slower on Mac (possibly related to time) #23419 (closed)
• `go test -bench=.` with `-benchtime=1x` is timing out at 2m and not running a single iteration of the benchmark #71446 (closed)
• go test -bench #24948 (closed)

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[JunyangShao]

@alandonovan @neild