testing: tiny benchmark with StopTimer runs forever

From at least Go 1,4 onward,

$ go version
go version devel +e03220a594 Sat Aug 25 02:39:49 2018 +0000 linux/amd64
$

If we run a tiny benchmark (count++) and use StopTimer() for initialization (count = 0) then the benchmark runs for a very long time, perhaps forever.

$ cat tiny_test.go
package main

import (
	"testing"
)

var count int64

func BenchmarkTiny(b *testing.B) {
	for n := 0; n < b.N; n++ {
		b.StopTimer()
		count = 0
		b.StartTimer()
		count++
	}
}
$

$ go test tiny_test.go -bench=.
goos: linux
goarch: amd64
BenchmarkTiny-4   	^Csignal: interrupt
FAIL	command-line-arguments	143.633s
$

If we comment out StopTimer() (//b.StopTimer()) then the benchmark quickly runs to completion.

$ cat tiny_test.go
package main

import (
	"testing"
)

var count int64

func BenchmarkTiny(b *testing.B) {
	for n := 0; n < b.N; n++ {
		// b.StopTimer()
		count = 0
		b.StartTimer()
		count++
	}
}
$

$ go test tiny_test.go -bench=.
goos: linux
goarch: amd64
BenchmarkTiny-4   	1000000000	         2.15 ns/op
PASS
ok  	command-line-arguments	2.374s
$

runtime.ReadMemStats which is called by both StartTimer and StopTimer is known to be slow, though I'm not sure it's expected to be as slow as shown here.

Calling just StartTimer without StopTimer is a noop because b.timerOn is true.

The uses of StartTimer/StopTimer are usually around one time setup/teardown code that happens before or after the b.N loop.

I suspect that this is (effectively) a duplicate of #20875.

@josharian

I encountered the same while benchmarking fairly small functions. Via pprof, I could see that ReadMemStats (called via both StartTimer and StopTimer) was taking up ~90% of the CPU time, while the func I was benchmarking was only taking about 3% of CPU time.

Initially, I too thought that go test -bench=. would never end. But that wasn't the problem.

For example, go test -bench=. -benchtime=100x runs fine. The issue is that when given a benchtime in a duration instead of number of iterations, the testing package has to estimate the number of times it will need to execute the benchmark loop.

And this is where it gets whacky. For example, on go test -bench=. -benchtime=0.1s, the total run-time ends up being over 6s on my machine. This seems to indicate that the b.N estimate that the testing package ends up with is way too high, as the time it spends running the benchmark is over 50 times larger than what the user wanted.

So I presume this is what you're seeing. By default the benchtime is 1s, so it's reasonable to think that your tiny benchmark could be slowed down enough to run for a few minutes. I'd suggest trying to run it with -benchtime=100x or -benchtime=0.01s to confirm that it's only the estimate that is wrong.

In which case I agree with @josharian that the root of the issue is #20875. If ReadMemStats wasn't called that often, I presume that the b.N estimates wouldn't be nearly as bad.

Looks like other people ran into very similar puzzling cases before: https://stackoverflow.com/questions/37620251/golang-benchmarking-b-stoptimer-hangs-is-it-me

This seems to indicate that the b.N estimate that the testing package ends up with is way too high

Note that if the goal is for the benchmark code to execute for 1s, and there's 97% overhead due to StopTimer/StartTimer, then the correct overall execution time is 33s. So maybe the b.N estimate is correct.

Note that we should make the b.N estimate better. CL 112155 is an attempt at this. It needs to be revisited. There's also discussion of this at #24735. See also
#27168 (comment).

I've also thought for some time that we should set an absolute limit on b.N. To mangle Tolstoy: How many iterations does one benchmark need? If we capped b.N at something reasonably sized, like 100k, that'd mitigate these disaster scenarios. And also general speed up running microbenchmarks. (I suppose I should file a new issue for this?)

remove StartTimer/StopTimer from the bench loop

Change https://golang.org/cl/257647 mentions this issue: testing: grow benchmark iteration incrementally

I've encountered this issue many many times in the past. Today again, it is so sad that the issue is still open. So I sent a CL and hope this could be closed.

Avoid rapid b.StartTimer and b.StopTimer in benchmarks

apd: avoid rapid b.StartTimer and b.StopTimer in benchmarks

Spent a couple hours figuring out what's wrong with my benchmarks since they run indefinitely. Just to find out that's the core issue. There should be a warning or other way to signal that rapid calls to StartTimer/StopTimer will make it run indefinitely or very long.

@JunyangShao

I had hoped there was some chance b.Loop might magically fix this issue, including there were some hints in some of the proposal discussions, such as #61515 (comment):

Given all of this, I think we could make testing.B.Loop target a real time rather than a benchmark time.

A quick test though seems to suggest that this problem still seems to occur with b.Loop.

If I update the example from the top comment above to instead use b.Loop and then do go test -bench=. -benchtime=1s, it runs a very long time. I killed it after ~10 minutes. It seems to spend most of its time in the kernel (perhaps getting the current time).

var count int64

func BenchmarkTinyBLoop(b *testing.B) {
	for b.Loop() {
		b.StopTimer()
		count = 0
		b.StartTimer()
		count++
	}
}

CC @JunyangShao, @aclements, if interested.

edit: I should have mentioned the test was with tip as of earlier today (go version devel go1.25-116b823 Wed Apr 2 11:25:15 2025 -0700 linux/amd64).

Benchmark fixes

Benchmark fixes (#7765)

I just ran into this when adding benchmarks to #70672.

It would be nice for there to at least be some kind of check if the benchmarking code is taking far more than the expected -benchtime (let's say 3-5x?) and output a warning with a link to this issue (given that it's a known issue for at least 7 years with very little progress).

os: optimise cgo clearenv

Change https://go.dev/cl/633515 mentions this issue: os: optimise cgo clearenv

syscall: optimise cgo clearenv

Navigation Menu

Repository navigation

testing: tiny benchmark with StopTimer runs forever #27217

1 remaining item

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

testing: tiny benchmark with StopTimer runs forever #27217

Description

Activity

meirf commented on Aug 25, 2018

josharian commented on Aug 26, 2018

mvdan commented on Jan 13, 2019

mvdan commented on Jan 13, 2019

josharian commented on Jan 13, 2019

1 remaining item

gopherbot commented on Sep 26, 2020

changkun commented on Sep 26, 2020

dangoodman commented on Feb 28, 2025

thepudds commented on Apr 2, 2025

cyphar commented on Sep 6, 2025

gopherbot commented on Sep 6, 2025

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions