cmd/compile,runtime: frequent test timeouts on solaris-amd64-oraclerel

[bcmills]

#!watchflakes
default <- builder == "solaris-amd64-oraclerel" && (pkg == "runtime" || pkg == "cmd/compile") && (`^panic: test timed out` || `failed to start: context deadline exceeded`)

greplogs --dashboard -md -l -e '(?ms)\Asolaris-amd64-oraclerel.*^panic: test timed out.*FAIL\s+runtime' --since=2022-01-01

2022-03-01T21:27:42-b0db2f0/solaris-amd64-oraclerel
2022-02-28T19:00:23-b33592d/solaris-amd64-oraclerel
2022-01-08T00:24:25-90860e0/solaris-amd64-oraclerel
2022-01-06T23:39:43-042548b/solaris-amd64-oraclerel

@golang/runtime: the builder appears to only run the -short tests. Is there something we can feasibly do to make -short mode shorter?

@golang/release, @rorth: would it make sense to set GO_TEST_TIMEOUT_SCALE on this builder to make the timeouts more generous?

[dmitshur]

It makes sense to increase GO_TEST_TIMEOUT_SCALE to me, but @rorth as the builder owner is in a better position to decide the optimal configuration for this builder. This builder is not configured as a TryBot, so if it needs more time, it's fine and won't affect pre-submit testing times (#17104).

[rorth]

"Bryan C. Mills" ***@***.***> writes:

@golang/release, @rorth: would it make sense to set `GO_TEST_TIMEOUT_SCALE` on this builder to make the timeouts more generous?

I'd be ok with that, but wondered about one thing: that zone is shared between the golang builder and an LLVM buildbot. The latter is restricted to 8 parallel jobs, and I'd been under the impression that the golang one would work with just 4 jobs. However, recently I've often seen way more than those 4 jobs. Have I just been deluded about that restriction, or has it somehow been lost?

[ianlancetaylor]

While running tests, a go builder will happily grab whatever resources it has available. Are you doing anything to restrict it to 4 jobs?

[rorth]

Hi Ian,

While running tests, a go builder will happily grab whatever resources it has available. Are you doing anything to restrict it to 4 jobs?

Not so far. When I inherited the builder, I was under the (obviously wrong) impression that this had been done in the builder config, similarly to buildbot for LLVM. So there's no similar facility available? I should be able to use CPU shares to achieve this. Setting up a separate zone just for the golang builder seems like a waste of effort (and IPv4 addresses).

[ianlancetaylor]

Good point, I think the builder config will set GOMAXPROCS, which will limit the resource usage of each specific test, but then you will have 4 tests run in parallel and each test will happily run 4 tests in parallel. At least, I think that is how it works; my apologies if I'm getting this wrong.

[rorth]

Ian Lance Taylor ***@***.***> writes:

Good point, I think the builder config will set `GOMAXPROCS`, which will limit the resource usage of each specific test, but then you will have 4 tests run in parallel and each test will happily run 4 tests in parallel. At least, I think that is how it works; my apologies if I'm getting this wrong.

As a first step, I've now set GOMAXPROCS=8 for the builder to see if this helps. The last runtime timeout happened before that change, though. We'll have to see if this is enough. In parallel, I'm also running the runtime test 10000 times in a loop on identical hardware (although on bare metal instead of a kernel zone/VM). Of the roughly 4000 runs completed so far, 6 have taken 2+ minutes rather than the usual 16-18 seconds. I missed the -test.timeout=3m, unfortunately, so all tests PASSed. Unfortunately, I couldn't easily see which subtest is timing out, otherwise I could restrict the testing to just that one if it's always the same one.

[bcmills]

As a first step, I've now set GOMAXPROCS=8 for the builder to see if
this helps. The last runtime timeout happened before that change,
though. We'll have to see if this is enough.

Appears not to be:

greplogs --dashboard -md -l -e '(?ms)\Asolaris-amd64-oraclerel.*^panic: test timed out.*FAIL\s+runtime' --since=2022-03-08

2022-03-29T16:24:51-a2baae6/solaris-amd64-oraclerel
2022-03-25T19:04:59-2bbf383/solaris-amd64-oraclerel
2022-03-25T15:15:57-3fd8b86/solaris-amd64-oraclerel

[bcmills]

greplogs --dashboard -md -l -e '(?ms)\Asolaris-amd64-oraclerel.*^panic: test timed out.*FAIL\s+runtime' --since=2022-03-30
2022-05-02T19:53:56-3b01a80/solaris-amd64-oraclerel

[bcmills]

greplogs -l -e '(?ms)\Asolaris-amd64-oraclerel.*^panic: test timed out.*FAIL\s+runtime' --since=2022-05-03
2022-05-11T03:28:01-ccb7987/solaris-amd64-oraclerel
2022-05-10T21:56:21-bda9da8/solaris-amd64-oraclerel

[bcmills]

greplogs -l -e '(?ms)\Asolaris-amd64-oraclerel.*^panic: test timed out.*FAIL\s+runtime' --since=2022-05-12
2022-05-25T19:25:08-04337a6/solaris-amd64-oraclerel
2022-05-23T16:21:22-c1d197a/solaris-amd64-oraclerel

[gopherbot]

Change https://go.dev/cl/408701 mentions this issue: dashboard: add known issue for solaris-amd64-oraclerel

[bcmills]

There have apparently not been any more of these failures since May. I'm calling this obsolete.

[gopherbot]

Change https://go.dev/cl/465156 mentions this issue: dashboard: unmark known-issues with low failure rates

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- builder == "solaris-amd64-oraclerel" && pkg == "runtime" && `^panic: test timed out`

2023-04-07 15:12 solaris-amd64-oraclerel go@39986d28 runtime.TestFakeTime (log)

panic: test timed out after 3m0s
running tests:
	TestFakeTime (32s)

runtime.syscall_wait4(0x30b3, 0xc0002b6018, 0x0, 0xc0023881b0)
	/opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/runtime/syscall_solaris.go:310 +0x85 fp=0xc00007e9f0 sp=0xc00007e998 pc=0x472225
syscall.Wait4(0xc000180008?, 0x0?, 0x0?, 0x0?)
	/opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/syscall/syscall_solaris.go:275 +0x26 fp=0xc00007ea38 sp=0xc00007e9f0 pc=0x480586
os.(*Process).wait(0xc000136270)
	/opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/os/exec_unix.go:43 +0x77 fp=0xc00007ea90 sp=0xc00007ea38 pc=0x4a22d7
os.(*Process).Wait(...)
	/opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/os/exec.go:132
os/exec.(*Cmd).Wait(0xc000166580)
	/opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/os/exec/exec.go:890 +0x45 fp=0xc00007eaf8 sp=0xc00007ea90 pc=0x531f45
os/exec.(*Cmd).Run(0x37?)
	/opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/os/exec/exec.go:590 +0x2d fp=0xc00007eb18 sp=0xc00007eaf8 pc=0x530b2d
os/exec.(*Cmd).CombinedOutput(0xc000166580)
	/opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/os/exec/exec.go:1005 +0x94 fp=0xc00007eb40 sp=0xc00007eb18 pc=0x532814
runtime_test.buildTestProg.func1()
	/opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/runtime/crash_test.go:143 +0x3d1 fp=0xc00007ed30 sp=0xc00007eb40 pc=0x6c6bd1
sync.(*Once).doSlow(0x7a9880?, 0xc001ab01b0?)
	/opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/sync/once.go:74 +0xbf fp=0xc00007ed90 sp=0xc00007ed30 pc=0x47c83f
sync.(*Once).Do(...)
	/opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/sync/once.go:65
runtime_test.buildTestProg(0xc0009049c0, {0x8188b8, 0xc}, {0xc000b84a00, 0x1, 0x1})
	/opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/runtime/crash_test.go:128 +0x48a fp=0xc00007ee88 sp=0xc00007ed90 pc=0x6c678a
runtime_test.TestFakeTime(0xc0009049c0)
	/opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/runtime/time_test.go:29 +0x87 fp=0xc00007ef70 sp=0xc00007ee88 pc=0x74f067
testing.tRunner(0xc0009049c0, 0x841278)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- builder == "solaris-amd64-oraclerel" && pkg == "runtime" && (`^panic: test timed out` || `failed to start: context deadline exceeded`)

2023-04-11 20:25 solaris-amd64-oraclerel go@28480216 runtime.TestCgoExternalThreadSIGPROF (log)

--- FAIL: TestCgoExternalThreadSIGPROF (0.01s)
    crash_cgo_test.go:98: /opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/tmp/go-build3722635515/testprogcgo.exe CgoExternalThreadSIGPROF failed to start: context deadline exceeded

2023-04-11 20:25 solaris-amd64-oraclerel go@28480216 runtime.TestCgoExecSignalMask (log)

--- FAIL: TestCgoExecSignalMask (0.00s)
    crash_cgo_test.go:137: /opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/tmp/go-build3722635515/testprogcgo.exe CgoExecSignalMask failed to start: context deadline exceeded

2023-04-11 20:25 solaris-amd64-oraclerel go@28480216 runtime.TestSigStackSwapping (log)

--- FAIL: TestSigStackSwapping (0.01s)
    crash_cgo_test.go:502: /opt/golang/tmp/workdir-host-solaris-oracle-amd64-oraclerel/tmp/go-build3722635515/testprogcgo.exe SigStack failed to start: context deadline exceeded

— watchflakes

[mknyszek]

In triage, it looks to us like all the tests are just timing out. The builder just seems slow. There might be one culprit. Verbose test output would tell us which test cases are slow.

CC @golang/solaris

[mknyszek]

I forgot that @golang/solaris is empty... CC @rorth I suppose?

[bcmills]

The C toolchain on this builder seems particularly slow. I wonder if just raising the GO_TEST_TIMEOUT_SCALE for the builder might resolve things.

[rorth]

"Bryan C. Mills" ***@***.***> writes:

The C toolchain on this builder seems particularly slow. I wonder if just raising the `GO_TEST_TIMEOUT_SCALE` for the builder might resolve things.

The buildlet is running in a kernel zone (VM), and for some reason some of the tests run extremely slow there, compared to bare metal on an identical server or the host system. For the time being, I've increased GO_TEST_TIMEOUT_SCALE to 4 as a workaround. Besides, I hope to migrate the buildlet to a different system (5 year old 2 x Xeon Gold 5120 instead of 12 year old 4 x Xeon E7540) in the coming months.

[bcmills]

Duplicate of #60152