cmd/go: -test.timeout=0 does not cancel go tool's test timeout

[dgryski]

Please answer these questions before submitting your issue. Thanks!

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

go 1.8beta2 ( go version devel +9cd3c0662a Thu Dec 15 20:06:07 2016 +0000 linux/amd64 )

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/dgryski/work/src/cvs/gocode:/home/dgryski/Dropbox/GITS/gocode/"
GORACE=""
GOROOT="/home/dgryski/work/src/cvs/go"
GOTOOLDIR="/home/dgryski/work/src/cvs/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build687665754=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

What did you do?

Running a benchmark with a number of sub-benchmarks and -count=20, my benchmarks were killed even though I provided -test.timeout=0.

I had a small (but slow, without updating the 10m timeout in the source code):

<dgryski@kamek[timeout] \ʕ◔ϖ◔ʔ/ > go test -test.bench=. -test.timeout=0
BenchmarkRun/0-4 	500000000	         3.40 ns/op
BenchmarkRun/1-4 	       1	60000158480 ns/op
BenchmarkRun/2-4 	       1	120000151589 ns/op
BenchmarkRun/3-4 	       1	180000159296 ns/op
SIGQUIT: quit
PC=0x453dc3 m=0 sigcode=0

goroutine 10 [syscall, 3 minutes]:
runtime.notetsleepg(0x5ea058, 0x37e11d4b9d, 0x16)
	/home/dgryski/work/src/cvs/go/src/runtime/lock_futex.go:205 +0x42 fp=0xc42002e760 sp=0xc42002e730
runtime.timerproc()
	/home/dgryski/work/src/cvs/go/src/runtime/time.go:209 +0x327 fp=0xc42002e7e0 sp=0xc42002e760
runtime.goexit()
	/home/dgryski/work/src/cvs/go/src/runtime/asm_amd64.s:2184 +0x1 fp=0xc42002e7e8 sp=0xc42002e7e0
created by runtime.addtimerLocked
	/home/dgryski/work/src/cvs/go/src/runtime/time.go:116 +0xed

goroutine 1 [chan receive, 10 minutes]:
testing.(*B).run1(0xc4200a6000, 0xc4200a6000)
	/home/dgryski/work/src/cvs/go/src/testing/benchmark.go:215 +0xac
testing.(*B).Run(0xc4200a62c0, 0x53a93b, 0xc, 0x542260, 0x4a8600)
	/home/dgryski/work/src/cvs/go/src/testing/benchmark.go:490 +0x1d1
testing.runBenchmarks.func1(0xc4200a62c0)
	/home/dgryski/work/src/cvs/go/src/testing/benchmark.go:403 +0x67
testing.(*B).runN(0xc4200a62c0, 0x1)
	/home/dgryski/work/src/cvs/go/src/testing/benchmark.go:140 +0xb2
testing.runBenchmarks(0xc42000ae20, 0x5e3b00, 0x1, 0x1, 0xc420020100)
	/home/dgryski/work/src/cvs/go/src/testing/benchmark.go:409 +0x48d
testing.(*M).Run(0xc420045f20, 0xc420045f20)
	/home/dgryski/work/src/cvs/go/src/testing/testing.go:823 +0x2df
main.main()
	github.com/dgryski/trifles/timeout/_test/_testmain.go:40 +0xf7

goroutine 6 [chan receive, 3 minutes]:
testing.(*B).run1(0xc4200a6420, 0xc4200a6420)
	/home/dgryski/work/src/cvs/go/src/testing/benchmark.go:215 +0xac
testing.(*B).Run(0xc4200a6000, 0xc4200da0c0, 0x1, 0xc4200da0d0, 0xc420031f00)
	/home/dgryski/work/src/cvs/go/src/testing/benchmark.go:490 +0x1d1
github.com/dgryski/trifles/timeout.BenchmarkRun(0xc4200a6000)
	/home/dgryski/Dropbox/GITS/gocode/src/github.com/dgryski/trifles/timeout/bench_test.go:11 +0xd0
testing.(*B).runN(0xc4200a6000, 0x1)
	/home/dgryski/work/src/cvs/go/src/testing/benchmark.go:140 +0xb2
testing.(*B).run1.func1(0xc4200a6000)
	/home/dgryski/work/src/cvs/go/src/testing/benchmark.go:213 +0x5a
created by testing.(*B).run1
	/home/dgryski/work/src/cvs/go/src/testing/benchmark.go:214 +0x7f

goroutine 19 [sleep, 3 minutes]:
time.Sleep(0x37e11d6000)
	/home/dgryski/work/src/cvs/go/src/runtime/time.go:59 +0xf7
github.com/dgryski/trifles/timeout.benchmarkSleep(0xc4200a6420, 0x37e11d6000)
	/home/dgryski/Dropbox/GITS/gocode/src/github.com/dgryski/trifles/timeout/bench_test.go:17 +0x43
github.com/dgryski/trifles/timeout.BenchmarkRun.func1(0xc4200a6420)
	/home/dgryski/Dropbox/GITS/gocode/src/github.com/dgryski/trifles/timeout/bench_test.go:11 +0x45
testing.(*B).runN(0xc4200a6420, 0x1)
	/home/dgryski/work/src/cvs/go/src/testing/benchmark.go:140 +0xb2
testing.(*B).run1.func1(0xc4200a6420)
	/home/dgryski/work/src/cvs/go/src/testing/benchmark.go:213 +0x5a
created by testing.(*B).run1
	/home/dgryski/work/src/cvs/go/src/testing/benchmark.go:214 +0x7f

rax    0xfffffffffffffffc
rbx    0x3b9ab59d
rcx    0x453dc3
rdx    0x0
rdi    0x5ea058
rsi    0x0
rbp    0xc42002e6e8
rsp    0xc42002e6a0
r8     0x0
r9     0x0
r10    0xc42002e6d8
r11    0x202
r12    0x0
r13    0x8
r14    0x0
r15    0xf3
rip    0x453dc3
rflags 0x202
cs     0x33
fs     0x0
gs     0x0
*** Test killed with quit: ran too long (10m0s).
FAIL	github.com/dgryski/trifles/timeout	600.004s

Source code here: https://play.golang.org/p/ubgEcN__zD

What did you expect to see?

The timeout was ignored and my long-running benchmarks completed.

What did you see instead?

Killed :(

[dgryski]

This happens even without using b.Run().

[ianlancetaylor]

In general -test.timeout=0 is ignored. If you use it, the default timeout of 10 minutes is used. Is there some doc somewhere indicating that -test.timeout=0 means that there is no timeout?

[dgryski]

On my phone at the moment but

go/src/testing/testing.go

Line 249 in 4bf7d1e

timeout = flag.Duration("test.timeout", 0, "fail test binary execution after duration `d` (0 means unlimited)")

is the message I remember seeing (from go test -help maybe?)

[ianlancetaylor]

Thanks. There is the timeout flag used by the testing package, and the timeout flag used by the go tool. The go tool passes its timeout flag to the testing package, so they seem like the same thing. But the go tool uses its timeout flag as a backup for the testing package timeout flag, and the go tool ignores a zero timeout rather than treating it as canceling the timeout. We should fix that.

[ALTree]

This is a dup of #14780

[ianlancetaylor]

So it is. Closing. Thanks.