testing: parent B.Cleanup() functions do not run if a sub-benchmark panics

[evanj]

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

$ go version
go version go1.20.4 darwin/arm64

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
GO111MODULE=""

GOARCH="arm64"

GOBIN=""

GOCACHE="/Users/evan.jones/Library/Caches/go-build"

GOENV="/Users/evan.jones/Library/Application Support/go/env"

GOEXE=""

GOEXPERIMENT=""

GOFLAGS=""

GOHOSTARCH="arm64"

GOHOSTOS="darwin"

GOINSECURE=""

GOMODCACHE="/Users/evan.jones/go/pkg/mod"

GONOPROXY=""

GONOSUMDB=""

GOOS="darwin"

GOPATH="/Users/evan.jones/go"

GOPRIVATE=""

GOPROXY=""

GOROOT="/opt/homebrew/Cellar/go/1.20.4/libexec"

GOSUMDB="sum.golang.org"

GOTMPDIR=""

GOTOOLDIR="/opt/homebrew/Cellar/go/1.20.4/libexec/pkg/tool/darwin_arm64"

GOVCS=""

GOVERSION="go1.20.4"

GCCGO="gccgo"

AR="ar"

CC="cc"

CXX="c++"

CGO_ENABLED="1"

GOMOD="/dev/null"

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 -fdebug-prefix-map=/var/folders/g1/97d8s0r57hj4nv4_qd3fqcrm0000gp/T/go-build3259637153=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

The following benchmark named BenchmarkSubBenchPanicNeverRunsCleanup calls b.Cleanup, then panics in a sub-benchmark. The "higher level" Cleanup functions never run, but the ones in the specific benchmark do. The equivalent code for a Test calling T.Cleanup(), the cleanup functions are run correctly. This is similar to bug as #41355, which had similar problems when panicing in a sub-test. I believe the parent functions should run.

package benchcleanup

import (
	"testing"
)

func BenchmarkSubBenchPanicNeverRunsCleanup(b *testing.B) {
	b.Cleanup(func() {
		println("top-level benchmark cleanup is never called")
	})
	b.Run("subbench_level_1", func(b *testing.B) {
		b.Cleanup(func() {
			println("sub-benchmark level 1 cleanup is never called")
		})
		b.Run("subbench_level_2", func(b *testing.B) {
			b.Cleanup(func() {
				println("sub-benchmark level 2 cleanup IS called")
			})
			panic("sub-benchmark level 2 panic")
		})
	})
}

func TestSubTestPanicNeverRunsCleanup(t *testing.T) {
	t.Cleanup(func() {
		println("top-level test cleanup is called")
	})
	t.Run("subbench_level_1", func(t *testing.T) {
		t.Cleanup(func() {
			println("sub-test level 1 cleanup is called")
		})
		t.Run("subbench_level_2", func(t *testing.T) {
			t.Cleanup(func() {
				println("sub-test level 2 cleanup is called")
			})
			panic("sub-test level 2 panic")
		})
	})
}

What did you expect to see?

The cleanup functions should be called.

What did you see instead?

Only the cleanup function in the same benchmark are called.

[bcmills]

Thanks for the report. Want to try a fix?

[evanj]

I took a look, and this probably requires a moderate change to how benchmarks are run. I have a sort-of fix and test, but it isn't completely right: it now swallows panics somewhere (but it does run the cleanup functions!). I think someone who understands more about the internals of the test/benchmark runner is going to need to take a look. I'll submit my not correct fix anyway, in case it is helpful.

It turns out that unlike for tests, a panic in a benchmark function is currently not caught at all, so it terminates the process. Tests have code to catch and propagate the panics and report them differently. This is why for my example I included, the test output includes [recovered] and additional testing package stack frames "on top of" the panic, while the benchmark output does not.

From go test . with the program above:

sub-test level 2 cleanup is called
sub-test level 1 cleanup is called
top-level test cleanup is called
--- FAIL: TestSubTestPanicNeverRunsCleanup (0.00s)
    --- FAIL: TestSubTestPanicNeverRunsCleanup/subbench_level_1 (0.00s)
        --- FAIL: TestSubTestPanicNeverRunsCleanup/subbench_level_1/subbench_level_2 (0.00s)
panic: sub-test level 2 panic [recovered]
	panic: sub-test level 2 panic

goroutine 36 [running]:
testing.tRunner.func1.2({0x100b995c0, 0x100bbc030})
	/opt/homebrew/Cellar/go/1.20.4/libexec/src/testing/testing.go:1526 +0x1c8
testing.tRunner.func1()
	/opt/homebrew/Cellar/go/1.20.4/libexec/src/testing/testing.go:1529 +0x384
panic({0x100b995c0, 0x100bbc030})
	/opt/homebrew/Cellar/go/1.20.4/libexec/src/runtime/panic.go:884 +0x204
example.com/benchcleanup.TestSubTestPanicNeverRunsCleanup.func2.2(0x0?)
	/Users/evan.jones/benchcleanup/benchcleanup_test.go:36 +0x3c
testing.tRunner(0x1400011cea0, 0x100bbbb70)
	/opt/homebrew/Cellar/go/1.20.4/libexec/src/testing/testing.go:1576 +0x10c
created by testing.(*T).Run
	/opt/homebrew/Cellar/go/1.20.4/libexec/src/testing/testing.go:1629 +0x368
FAIL	example.com/benchcleanup	0.252s
FAIL

From go test . -run=none -bench=. with the program above:

sub-benchmark level 2 cleanup IS called
panic: sub-benchmark level 2 panic

goroutine 11 [running]:
example.com/benchcleanup.BenchmarkSubBenchPanicNeverRunsCleanup.func2.2(0x14000074a00?)
	/Users/evan.jones/benchcleanup/benchcleanup_test.go:19 +0x3c
testing.(*B).runN(0x14000074a00, 0x1)
	/opt/homebrew/Cellar/go/1.20.4/libexec/src/testing/benchmark.go:193 +0x12c
testing.(*B).run1.func1()
	/opt/homebrew/Cellar/go/1.20.4/libexec/src/testing/benchmark.go:233 +0x50
created by testing.(*B).run1
	/opt/homebrew/Cellar/go/1.20.4/libexec/src/testing/benchmark.go:226 +0x90
exit status 2
FAIL	example.com/benchcleanup	0.151s
FAIL

[gopherbot]

Change https://go.dev/cl/494635 mentions this issue: testing: ensure B.Cleanup() runs if benchmark panics