cmd/go: timeout in TestCache* on darwin-amd64-10_12

[bcmills]

From darwin-amd64-10_12 (https://build.golang.org/log/9f4a33126668c564bf4bddb208bc9c6af1b7d149):

panic: test timed out after 9m0s
[…]
goroutine 657 [syscall]:
syscall.syscall6(0x10af9b0, 0x5204, 0xc00046ecb4, 0x0, 0xc0003945a0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/runtime/sys_darwin.go:74 +0x2e
syscall.wait4(0x5204, 0xc00046ecb4, 0x0, 0xc0003945a0, 0x90, 0x16e5c00, 0x1)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/syscall/zsyscall_darwin_amd64.go:44 +0x87
syscall.Wait4(0x5204, 0xc00046ed04, 0x0, 0xc0003945a0, 0x1c041a0, 0x1, 0x1d42b28)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/syscall/syscall_bsd.go:129 +0x51
os.(*Process).wait(0xc000504240, 0x17582e0, 0x17582e8, 0x17582d8)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/os/exec_unix.go:38 +0x7b
os.(*Process).Wait(...)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/os/exec.go:125
os/exec.(*Cmd).Wait(0xc000434580, 0x0, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/os/exec/exec.go:501 +0x60
os/exec.(*Cmd).Run(0xc000434580, 0x6d, 0xc00041a460)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/os/exec/exec.go:341 +0x5c
cmd/go_test.(*testgoData).doRun(0xc0003a2d80, 0xc00041a460, 0x5, 0x5, 0xc00004bc00, 0x1d42b28)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/cmd/go/go_test.go:484 +0x2b7
cmd/go_test.(*testgoData).run(0xc0003a2d80, 0xc00041a460, 0x5, 0x5)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/cmd/go/go_test.go:500 +0x7d
cmd/go_test.TestCacheCoverage(0xc0000e4c00)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/cmd/go/go_test.go:5277 +0x2c3
testing.tRunner(0xc0000e4c00, 0x1757128)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/testing/testing.go:916 +0xc1
created by testing.(*T).Run
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/testing/testing.go:967 +0x351
[…]
goroutine 679 [syscall]:
syscall.syscall6(0x10af9b0, 0x5266, 0xc00060d964, 0x0, 0xc0004b0480, 0x0, 0x0, 0x0, 0x0, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/runtime/sys_darwin.go:74 +0x2e
syscall.wait4(0x5266, 0xc00060d964, 0x0, 0xc0004b0480, 0x90, 0x16e5c00, 0x1)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/syscall/zsyscall_darwin_amd64.go:44 +0x87
syscall.Wait4(0x5266, 0xc00060d9b4, 0x0, 0xc0004b0480, 0x1c041a0, 0x1, 0x1d42460)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/syscall/syscall_bsd.go:129 +0x51
os.(*Process).wait(0xc00002c690, 0x17582e0, 0x17582e8, 0x17582d8)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/os/exec_unix.go:38 +0x7b
os.(*Process).Wait(...)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/os/exec.go:125
os/exec.(*Cmd).Wait(0xc00054c840, 0x0, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/os/exec/exec.go:501 +0x60
os/exec.(*Cmd).Run(0xc00054c840, 0x6d, 0xc0000f9740)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/os/exec/exec.go:341 +0x5c
cmd/go_test.(*testgoData).doRun(0xc0003a3200, 0xc0000f9740, 0x3, 0x3, 0xc0002ae400, 0x1d42460)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/cmd/go/go_test.go:484 +0x2b7
cmd/go_test.(*testgoData).run(0xc0003a3200, 0xc0000f9740, 0x3, 0x3)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/cmd/go/go_test.go:500 +0x7d
cmd/go_test.TestTestCacheInputs(0xc0000e5200)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/cmd/go/go_test.go:5607 +0x2378
testing.tRunner(0xc0000e5200, 0x17577f0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/testing/testing.go:916 +0xc1
created by testing.(*T).Run
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/testing/testing.go:967 +0x351

It's not obvious to me whether this is due to a bug in cmd/go or the same underlying platform issue as #25696.

CC @jayconrod @ianlancetaylor

[ianlancetaylor]

The stack trace just shows the test program waiting for the invocation of go test -cover -short math strings to complete. I guess we should put a timeout on the execution of the subprogram. Maybe we could use the new t.Deadline in testgoData.doRun. Or rewrite the test to be a script test.

[bcmills]

Rewriting to a script test sounds like a great idea — we already set a timeout in those.

[prattmic]

greplogs --dashboard -md -l -e 'FAIL: TestCacheCoverage'

2022-11-28T23:32:00-318e75b/darwin-amd64-aws-race
2022-11-23T23:15:01-920f87a/darwin-amd64-aws-race
2022-11-18T20:22:20-6fc1f4f/darwin-amd64-aws-race
2021-03-04T17:55:25-2d30c94/windows-amd64-longtest
2020-04-27T17:49:51-8af8fa9/windows-amd64-longtest
2020-03-01T21:04:30-a4f7b08/darwin-amd64-nocgo
2019-11-08T17:01:18-a762221/linux-amd64-clang

[bcmills]

Hmm. The timeout suggested in #35278 (comment) was added (implicitly by (*testgoData).doRun) in CL 450697, and you can see in the SIGQUIT stack trace that it produced in the 2022-11-28 run that there were a few runnable goroutines at the time.

And the failures in 2022 are all on darwin-.*-race builders.

So I'm inclined to suspect one of two things:

1. Maybe the darwin-amd64-race builders are just slow, and need a GO_TEST_TIMOUT_SCALE (like the one we currently have for windows-amd64-race)?
2. Maybe there is some runtime bug on darwin-amd64-race that causes Go programs to (rarely) deadlock for some reason? (Perhaps something related to runtime: async signals not reliably delivered to Go threads under TSAN #18717?)

[prattmic]

These Darwin builders moved from MacStadium to AWS, so I wouldn't be surprised if timing is a bit different there.

[bcmills]

Duplicate of #58919