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

testing: tiny benchmark with StopTimer runs forever #27217

Open
peterGo opened this issue Aug 25, 2018 · 8 comments
Open

testing: tiny benchmark with StopTimer runs forever #27217

peterGo opened this issue Aug 25, 2018 · 8 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@peterGo
Copy link
Contributor

peterGo commented Aug 25, 2018

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
$ 
@peterGo peterGo changed the title testing: tiny benchmarks with StopTimer run forever testing: tiny benchmark with StopTimer runs forever Aug 25, 2018
@ianlancetaylor ianlancetaylor added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Aug 25, 2018
@ianlancetaylor ianlancetaylor added this to the Go1.12 milestone Aug 25, 2018
@meirf
Copy link
Contributor

meirf commented Aug 25, 2018

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.

@josharian
Copy link
Contributor

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

@mvdan
Copy link
Member

mvdan commented Jan 13, 2019

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.

@mvdan
Copy link
Member

mvdan commented Jan 13, 2019

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

@josharian
Copy link
Contributor

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?)

mvdan added a commit to mvdan/benchinit that referenced this issue Jan 14, 2019
It can completely mess up the benchmark numbers for init functions that
were too small. Moreover, it could make the -benchtime estimates be way
off. For example, 'benchinit cmd/go' was taking over a minute to run the
benchmark, instead of the expected ~1s.

The benchtime estimate being off is likely the upstream issue
golang/go#27217.

The fact that StartTimer and StopTimer are expensive is being tracked in
golang/go#20875.
@andybons andybons modified the milestones: Go1.12, Go1.13 Feb 12, 2019
@andybons andybons modified the milestones: Go1.13, Go1.14 Jul 8, 2019
@rsc rsc modified the milestones: Go1.14, Backlog Oct 9, 2019
@bobg
Copy link

bobg commented Aug 13, 2020

I have some code that exhibits this problem too. You can reproduce it by uncommenting the StopTimer at https://github.com/bobg/hashsplit/blob/079f00442fd17ce40e5155970227f63e6e1b7f5c/rollsum_test.go#L36.

@gopherbot
Copy link

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

@changkun
Copy link
Member

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.

nvanbenschoten added a commit to nvanbenschoten/apd that referenced this issue Jan 1, 2022
They cause the benchmarks to run for a very long time.
See golang/go#27217.

Adjust the benchmarks to have an explicit setup phase
and run phase, separated by `b.ResetTimer`.
nvanbenschoten added a commit to nvanbenschoten/apd that referenced this issue Jan 1, 2022
They cause the benchmarks to run for a very long time.
See golang/go#27217.

Adjust the benchmarks to have an explicit setup phase
and run phase, separated by `b.ResetTimer`.
nvanbenschoten added a commit to nvanbenschoten/apd that referenced this issue Jan 3, 2022
They cause the benchmarks to run for a very long time.
See golang/go#27217.

Adjust the benchmarks to have an explicit setup phase
and run phase, separated by `b.ResetTimer`.
nvanbenschoten added a commit to nvanbenschoten/apd that referenced this issue Jan 5, 2022
They cause the benchmarks to run for a very long time.
See golang/go#27217.

Adjust the benchmarks to have an explicit setup phase
and run phase, separated by `b.ResetTimer`.
nvanbenschoten added a commit to nvanbenschoten/apd that referenced this issue Jan 6, 2022
They cause the benchmarks to run for a very long time.
See golang/go#27217.

Adjust the benchmarks to have an explicit setup phase
and run phase, separated by `b.ResetTimer`.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

10 participants