testing: Benchmark calls during benchmarks deadlock

empijei commented 5 years ago

What version of Go are you using (`go version`)?

$ go version
go version go1.11.2 linux/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (`go env`)?

go env Output

$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="REDACTED"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="REDACTED"
GOPROXY=""
GORACE=""
GOROOT="/usr/lib/google-golang"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/google-golang/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
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=/tmp/go-build117573359=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Called testing.Benchmark in a Benchmark. The reason for this is that I wanted to check during benchmarks which one of two possible implementations would be faster on the current machine and for a set of given inputs.

Here is a minimal repro that should be run as a benchmark to crash (must be in *_test.go and should be run with go test -bench=. )

package foo

func Foo(n int) {
    // Dummy function to benchmark
    for i := 0; i < n; i++ {
        time.Sleep(time.Nanosecond)
    }
}

func BenchmarkFoo(b *testing.B) {
    res1 := testing.Benchmark(func(b *testing.B) {
        for i := 0; i < b.N; i++ {
            Foo(1)
        }
    })
    res2 := testing.Benchmark(func(b *testing.B) {
        for i := 0; i < b.N; i++ {
            Foo(2)
        }
    })
    b.Logf("Difference between executions is ~%dns", res2.NsPerOp()-res1.NsPerOp())
}

What did you expect to see?

"Difference between executions is ~1ns

What did you see instead?

goroutine 1 [chan receive]:
testing.(*B).run1(0xc000096000, 0xc000096000)
        /usr/lib/google-golang/src/testing/benchmark.go:216 +0x9e
testing.(*B).Run(0xc000096340, 0x5358f5, 0xc, 0x53d380, 0x4abe00)
        /usr/lib/google-golang/src/testing/benchmark.go:514 +0x26c
testing.runBenchmarks.func1(0xc000096340)
        /usr/lib/google-golang/src/testing/benchmark.go:416 +0x78
testing.(*B).runN(0xc000096340, 0x1)
        /usr/lib/google-golang/src/testing/benchmark.go:141 +0xb2
testing.runBenchmarks(0x0, 0x0, 0xc00007e060, 0x616150, 0x1, 0x1, 0x80)
        /usr/lib/google-golang/src/testing/benchmark.go:422 +0x323
testing.(*M).Run(0xc0000b4000, 0x0)
        /usr/lib/google-golang/src/testing/testing.go:1042 +0x37c
main.main()
        _testmain.go:42 +0x13d

goroutine 7 [chan receive]:
testing.(*B).run1(0xc0000964e0, 0xc0000964e0)
        /usr/lib/google-golang/src/testing/benchmark.go:216 +0x9e
testing.Benchmark(0x53d370, 0x0, 0x0, 0x0, 0x0, 0x0)
        /usr/lib/google-golang/src/testing/benchmark.go:658 +0xd6
_/MYHOME/tmp/benchbug.BenchmarkFoo(0xc000096000)
        /MYHOME/tmp/benchbug/foo_test.go:16 +0x3f
testing.(*B).runN(0xc000096000, 0x1)
        /usr/lib/google-golang/src/testing/benchmark.go:141 +0xb2
testing.(*B).run1.func1(0xc000096000)
        /usr/lib/google-golang/src/testing/benchmark.go:214 +0x5a
created by testing.(*B).run1
        /usr/lib/google-golang/src/testing/benchmark.go:207 +0x7d

goroutine 22 [semacquire]:
sync.runtime_SemacquireMutex(0x639c04, 0x0)
        /usr/lib/google-golang/src/runtime/sema.go:71 +0x3d
sync.(*Mutex).Lock(0x639c00)
        /usr/lib/google-golang/src/sync/mutex.go:134 +0xff
testing.(*B).runN(0xc0000964e0, 0x1)
        /usr/lib/google-golang/src/testing/benchmark.go:131 +0x31
testing.(*B).run1.func1(0xc0000964e0)
        /usr/lib/google-golang/src/testing/benchmark.go:214 +0x5a
created by testing.(*B).run1
        /usr/lib/google-golang/src/testing/benchmark.go:207 +0x7d
exit status 2
FAIL    _/MYHOME/tmp/benchbug       0.022s

Probable cause

During the first iteration of benchFunc run1 is executed. run1 invokes runN which will run run1. The issue is that runN tries to acquire a global lock while holding it, causing the deadlock.

Source for runN:

// runN runs a single benchmark for the specified number of iterations.
func (b *B) runN(n int) {
    benchmarkLock.Lock() // ← acquiring global mutex
    defer benchmarkLock.Unlock()
    // Try to get a comparable environment for each run
    // by clearing garbage from previous runs.
    runtime.GC()
    b.raceErrors = -race.Errors()
    b.N = n
    b.parallelism = 1
    b.ResetTimer()
    b.StartTimer()
    b.benchFunc(b) // ← This will run run1, which will call runN, which will deadlock

Source for run1:

// run1 runs the first iteration of benchFunc. It returns whether more
// iterations of this benchmarks should be run.
func (b *B) run1() bool {
    if ctx := b.context; ctx != nil {
        // Extend maxLen, if needed.
        if n := len(b.name) + ctx.extLen + 1; n > ctx.maxLen {
            ctx.maxLen = n + 8 // Add additional slack to avoid too many jumps in size.
        }
    }
    go func() {
        // Signal that we're done whether we return normally
        // or by FailNow's runtime.Goexit.
        defer func() {
            b.signal <- true
        }()

        b.runN(1) // ← Running runN
    }()
    <-b.signal

mvdan commented 5 years ago

Are calls to testing.Benchmark within a benchmark supported? But I agree that something is wrong. Even if they're not supported, the testing package should error properly instead of deadlocking.

empijei commented 5 years ago

Current doc states

Benchmark benchmarks a single function. Useful for creating custom benchmarks that do not use the "go test" command.

Should this be corrected to something that specifies it should only be used for those cases that do not use "go test" or it is clear enough and I just misread it?

dtracers commented 4 years ago

What is the proper way to compare speeds of functions as a part of go test?

If I want to average a bunch of separate benchmarks together for example of different file sizes what would be the proper way to do it?

golang / go