I've been looking at this problem on various systems. If I run 'go tool dist test go_test:runtime' by itself the time varies and sometimes on a power8 it times out, but never on a power9 because it is faster there. But one mysterious result is that if I set GOMAXPROCS to a smaller value, like 2, 4, or 8 then the time is small enough on the power8 so that it doesn't time out. I thought these VMs only had 2 processors each, which I thought was equivalent to running GOMAXPROCS=2. I can only get it to timeout if the number of processors is > 150.

I don't know if this is related, but a while back I had a bunch of timeouts in my personal OSU power9 system. I asked them to increase it from 2 to 4 cores and 4 to 8GB RAM and now I have zero timeouts there. Maybe these builders are timing out because they have too little CPU time allocated to them in the hypervisor.

@bradfitz can correct me if I'm wrong, but IIRC, the power8 builders are 2 core, 4GB RAM only.

It's not clear to me whether the test is hung or just slow. Perhaps we should set a GO_TEST_TIMEOUT_SCALE on this builder and see if that helps?

@dmitshur I think we need to increase the GO_TEST_TIMEOUT_SCALE for all the linux ppc64* builders. I can make the change but don't know how those are tested.

@laboger Sounds good. GO_TEST_TIMEOUT_SCALE is a part of builder configuration, it doesn't need tests. See CL 158537 for a past example.

Change https://golang.org/cl/300870 mentions this issue: build: increase GO_TEST_TIMEOUT_SCALE for ppc64 builders

This turns out not to be specific to the ppc64le builder. I think the runtime tests are just getting too slow in short mode in general.

(CC @jeremyfaller)

This may be the same underlying issue as #45885.

greplogs --dashboard -md -l -e '(?ms)test timed out.*runtime_test\.(?:run|runBuil[dt]|build)TestProg.*FAIL\s+runtime' --since=2021-05-01

This is affecting at least five different builders, with many failures per month.

I think that makes it a release-blocker via #11811. All of the builders need to be passing tests reliably — if that means skipping more tests on non-longtest builders, we may need to prioritize which tests to run, or perhaps move some of the slower ones out to some package that won't also be run by users as part of go test all in their own modules. (Compare #48770.)

Looking at the solaris-amd64-oraclerel timeouts, many of the process wait times are quite long (1–2 minutes).

That makes me wonder whether these timeouts are actually deadlocks — perhaps related to the ones observed in #48789?

#49614 also shows an apparent deadlock with processes blocked in runtime.syscall_wait4. (It may be a duplicate of this issue.)

It's interesting to note that in all the recent Solaris failures the runtime test times out while building a test with build flags, either from TestCgoExternalThreadSignal (building testprogcgo with -tags=threadprof) or TestCheckPtr (building testprog with -gcflags=all=-d=checkptr=1). The buildTestProg function serializes all builds using a mutex. It does a separate build for each binary (testprog, testprogcgo, ....) and the additional arguments being passed to go build, typically none but sometimes, as in these cases, present. Building testprogcgo naturally requires invoking the C compiler a few times, and also the C linker. So overall these extra builds could definitely slow down the test. Still hard to see how it takes as long as it does, though.

Change https://golang.org/cl/364654 mentions this issue: runtime: don't serialize all builds in test

in all the recent Solaris failures the runtime test times out while building a test with build flags

That is a strong pattern but not universal. The stack traces for the failures listed in #49614 seem to be at a point where the test is running the compiled program (and has been for over a minute), not waiting on a build process.

After CL 364654 the time required to run the runtime tests on a Solaris system I have access to drops from 70 seconds to 51 seconds. CL 364755, if submitted, will drop it farther. I don't know if timeouts are the problem here, but they may be part of it. But there may also be a different problem.

Seems like a good start, at least. We can watch the builders for a while and see whether it is empirically fixed.

The last timeout in these functions was before the aforementioned changes, so I'm provisionally marking this as fixed.
(The reduction in these timeouts did draw my attention to a different runtime timeout, which I have filed as #49680.)

greplogs --dashboard -md -l -e '(?ms)test timed out.*runtime_test\.(?:run|runBuilt|build)TestProg.*FAIL\s+runtime' --since=2021-11-17

2021-11-17T18:14:41-0981724/openbsd-386-68

Nope, still timing out occasionally:

greplogs --dashboard -md -l -e '(?ms)test timed out.*runtime_test\.(?:run|runBuilt|build)TestProg.*FAIL\s+runtime' --since=2021-11-20

2021-11-22T20:34:40-f13fcd9/solaris-amd64-oraclerel

In the 2021-11-22 timeout the only tests still running are two waiting for go build -tags=threadprof testprogcgo to complete.

On a Solaris system I have access to, clearing the cache and running go test -test.short -test.v -test.count=1 runtime takes 38.5 seconds. The last two tests to complete are TestCgoExternalThreadSIGPROF and TestCgoExternalThreadSignal which both take about 13 seconds. One test is building the test program, and the other is waiting for that build to complete (they both build the same test program). Actually running the test program takes a fraction of a second.

This is consistent with the builder failure just being slow and running out of time, especially since cmd/dist will be running other tests in parallel.

greplogs --dashboard -md -l -e '(?ms)test timed out.*runtime_test\.(?:run|runBuilt|build)TestProg.*FAIL\s+runtime' --since=2021-11-23

2021-12-02T22:06:27-06dbf61/solaris-amd64-oraclerel
2021-12-02T20:45:47-3c6295d/openbsd-386-68
2021-11-29T19:24:34-68da368/solaris-amd64-oraclerel
2021-11-24T15:57:53-14f2b2a/openbsd-386-68
2021-11-24T15:55:56-465b402/openbsd-386-68
2021-11-24T15:55:56-465b402/solaris-amd64-oraclerel

All of these timeouts also appear to be actively compiling in TestCgoExternalThread.*.

Perhaps some of these slower tests should be skipped in short mode?

Perhaps some of these slower tests should be skipped in short mode?

Since we don't have a long builder for these, this seems like it would lose important test coverage.

or perhaps move some of the slower ones out to some package that won't also be run by users as part of go test all in their own modules.

This seems feasible. As you pointed out, this would give it its own timeout. It would require some nontrivial refactoring to pull out the testprog infrastructure, but we could do that.

greplogs --dashboard -md -l -e '(?ms)test timed out.*runtime_test\.(?:run|runBuilt|build)TestProg.*FAIL\s+runtime' --since=2021-12-07

2022-01-06T23:39:43-042548b/solaris-amd64-oraclerel (building TestFakeTime)
2022-01-06T15:00:16-da7891f/netbsd-386-9_0-n1 (running TestCgoExecSignalMask)
2022-01-03T23:45:06-a893d0f/openbsd-386-68 (building TestCgoExternalThreadSIGPROF)
2021-12-22T23:31:40-d2ce939/solaris-amd64-oraclerel (building TestCgoExternalThreadSignal)
2021-12-16T21:02:37-ea26ce7/netbsd-arm64-bsiegert (building TestFakeTime)
2021-12-13T19:40:29-7bdbc73/openbsd-386-68 (building TestCgoExternalThreadSIGPROF)
2021-12-12T14:36:17-6b89773/solaris-amd64-oraclerel (building TestCgoExternalThreadSIGPROF)

A much simpler thing we could do is to increase the timeout for the runtime test. We already do this for the cmd/go tests [1] and I don't think that's any more artificial than factoring the cgo prog tests out into their own test.

[1] Or, at least, we try to. The code is weird.

If increasing the timeout fixes the builder flakiness, I think it's a reasonable approach — Go users who run go test all should in general expect to either set a very generous timeout or scale it to their particular running environment.

That said, if the problem is just the timeout length, should we raise the scale factors in x/build/dashboard/builders.go instead of just for the specific test?

(It would be nice if we could eliminate the cmd/go special case in that code too, but that seems like a separate issue...)

The timeouts are from building a variant of threadprogcgo with -tags=threadprof. We don't need that variant. I'll send a CL to remove it. That will remove the extra build time and should keep the tests from timing out. I hope.

Change https://golang.org/cl/379294 mentions this issue: runtime: remove -tags=threadprof in tests