Golang benchmarking b.StopTimer() hangs -- is it me?

Question

I've run into a problem benchmarking my Go programs, and it looks to me like a Go bug. Please help me understand why it's not.

In a nutshell: benchmarking hangs when I call b.StopTimer() even if I then call b.StartTimer() afterwards. AFAICT I am using the functions as intended.

This is on Mac OSX 10.11.5 "El Capitan," with go version go1.6.1 darwin/amd64; everything else seems to be fine. I will try to check this on Linux later today and update the question.

Here's the code. Run with go test -bench=. as usual.

package bmtimer

import (
    "testing"
    "time"
)

// These appear to not matter; they can be very short.
var COSTLY_PREP_DELAY = time.Nanosecond
var RESET_STATE_DELAY = time.Nanosecond

// This however -- the measured function delay -- must not be too short.
// The shorter it is, the more iterations will be timed.  If it's infinitely
// short then you will hang -- or perhaps *appear* to hang?
var FUNCTION_OF_INTEREST_DELAY = time.Microsecond

func CostlyPrep()         { time.Sleep(COSTLY_PREP_DELAY) }
func ResetState()         { time.Sleep(RESET_STATE_DELAY) }
func FunctionOfInterest() { time.Sleep(FUNCTION_OF_INTEREST_DELAY) }

func TestPlaceHolder(t *testing.T) {}

func BenchmarkSomething(b *testing.B) {

    CostlyPrep()
    b.ResetTimer()

    for n := 0; n < b.N; n++ {

        FunctionOfInterest()
        b.StopTimer()
        ResetState()
        b.StartTimer()
    }
}

Thanks in advance for any tips! I've come up short on Google as well as here.

Edit: It seems this only happens of FunctionOfInterest() is really fast; and yes, I specifically want to do this inside my benchmark loop. I've updated the sample code to make that more clear. And I think I have it figured out now.

Gauger

The plot thickens! Could it be that this only hangs for very fast operations? If I call CostlyPrep() instead of FunctionOfInterest() then suddenly it works. – Gauger

StopTimer blocks on a call to runtime.ReadMemStats, which requires a stopTheWorld call. You basically shouldn't be stopping and starting the timer in the benchmark loop. – Soften

Ya, there shouldn't be 'prep' inside the loop, all prep (and consequently all time manipulation) should be done before entering the benchmark loop. – Vesicate

Thanks @JimB, but the docs strongly imply that I can do it if I have the need. In fact the way I read it, that's precisely what these are for, because you should be using b.ResetTimer() for any prep that happens before the benchmark loop. I get that it's not optimal but -- also to @user114241 on this -- there absolutely are cases where you have to fiddle with state in the benchmark loop in order for the benchmark to be meaningful. You then need to factor out the time spent fiddling, one way or another. – Gauger

oh yes, sorry, it shouldn't affect the timing. Run the benchmark with gctrace and see what's going on. I think that's probably what's interfering. – Soften

Thanks @JimB, your previous comment pointed me to the answer! :-) – Gauger

Possibly relevant: github.com/golang/go/issues/27217 – Sines

This is indeed a known, still unsolved issue. As a workaround, for benchmarked functions that are otherwise fast, Daniel Martí recommends passing the desired number of iterations to the benchtime flag rather than setting the desired benchmark duration (or relying on the default one of 1s): for instance, use -benchtime=100x. – Exoskeleton

Answer 1

TL;DR: it's not a bug, it's just a little tricky.

I'm pretty sure I know what's going on. The use of StopTimer and StartTimer inside the benchmarking loop is not the problem; the problem is that the function I do want to test is too fast for its own good. Or for my good anyway.

By adjusting the sleep time used by that function, we can pretty easily observe the benchmarking differences. At least for something this simple, Go is running more iterations the faster the measured code returns. This is known behavior and I should have thought of it. One finds output like this:

PASS
BenchmarkSomething-4     1000000          2079 ns/op
ok      bmtimer 36.587s

When the FunctionOfInterest returns very fast -- or of course "infinitely" fast, as in func tooFast() {} -- then Go keeps running more iterations of it, trying to get a reliable benchmark. You might run out of patience. Or, your computer might:

*** Test killed with quit: ran too long (10m0s).
FAIL    bmtimer 600.037s

(That was ten minutes at 100% CPU on one core.)

The good news of course is that it's not a bug; the bad news is it's still pretty annoying that it doesn't just stop at, say, a million iterations and tell you its best guess.

But then again, the other good news is that encountering this problem indicates your function is fast enough and probably doesn't need benchmarking.

The remaining mystery is: Why does this only happen when we stop and start the timer?

Without fiddling with the timer, I can call my noop function and it benchmarks it just fine, in a mere two billion iterations:

BenchmarkSomething-4    2000000000           0.33 ns/op
ok      bmtimer 0.706s

My best guess is based on the comment from @JimB -- stopping the world takes at least a little time, and when you're running two billion iterations that can easily run over ten minutes. Like the man said: a billion here, a billion there, and pretty soon you're talking about real money.

(That's my guess anyway. Smarter folks than I may yet correct me.)

Thus the moral of our story is: yes by all means do take advantage of b.StopTimer() and b.StartTimer() in order to handle state if you have no other way to deal with it. But keep in mind that for very fast functions, it may be too much for the benchmarker.

I do wish I knew a better way to isolate the specific function benchmark for fast functions. My initial hack that I used before trying StopTimer was to have another benchmark function that benchmarks just the extra code, so you'd get two numbers: ns/op with everything, and ns/op without the function of interest. That works, and it's probably even more accurate than stopping the timer, but it does require advance knowledge of how to interpret the benchmark output.

Gauger

Answer 2

This is a known issue with benchmarking in Go and is tracked here.

As mentioned in this comment, you can run the benchmark with the flag -benchtime=100x or -benchtime=0.01s to ensure that it doesn't run for longer than desired.

Torrietorrin