x/build: OpenBSD 7.0 386 builder is slow

[heschi]

I am about 80% sure that the OpenBSD builders, both 6.8 and 7.0, are timing out running all.bash. We have a hard 30 minute limit on build VMs, and the OpenBSD builders take slightly longer than that to run all.bash from scratch. However, they write a snapshot of the distribution after it's built, and reusing that saves enough time for the build to succeed upon retry -- that's why the dashboard is relatively clean-looking.

This is wasteful. We should probably increase the timeout so that the build finishes, prevent the retry, or modify the OpenBSD tests somehow to run in a more reasonable amount of time.

cc @golang/release @4a6f656c

[bcmills]

This is wasteful. We should probably increase the timeout so that the build finishes, prevent the retry, or …

#42699 makes a similar observation about TryBot stalls and retries.

[bcmills]

The openbsd-386-70 builder has been struggling for quite a long time now, and it has only completed a couple of builds for the many CLs that were merged over the past few days:

It sounds like the plan is just to raise the timeout — is this blocked on anything in particular?

[heschi]

I said I'd do it and then disappeared in a puff of smoke for two weeks. Mailing now.

[gopherbot]

Change https://golang.org/cl/382978 mentions this issue: dashboard: allow 45 minutes for 386 OpenBSD builds

[heschi]

Maybe there was more than one thing going on. OpenBSD 6.8 386 is clean, perhaps because of this change or perhaps not. 7.0, however, is still failing even after (I believe) the change has taken effect. See attached.

builder openbsd-386-70.txt

It seems that cgo_test is hanging. Retitling.

[heschi]

@ianlancetaylor

I'm going to call this a release blocker until it's investigated.

[ianlancetaylor]

On a gomote the cgo_test takes 22 seconds to run. I don't think there is anything specific to cgo here.

In the log attached above everything seems to be slow. I see things like

  2022-02-04T17:24:20Z run_tests_multi 10.128.15.199:80: [go_test:container/heap go_test:container/list go_test:container/ring]
  2022-02-04T17:24:29Z finish_run_tests_multi after 8.61s; 10.128.15.199:80: [go_test:container/heap go_test:container/list go_test:container/ring]

...

ok  	container/heap	0.058s
ok  	container/list	0.047s
ok  	container/ring	0.049s

The log suggests that it takes 8.61 seconds to run the container/heap, container/list, and container/ring tests. But when reporting the actual test times, the total is 0.15 seconds. The latter time probably doesn't include the time that it takes to build the tests, but of course that shouldn't be very long either; on a gomote each takes about 1 second to build.

I don't know what is going here but I don't think it's cgo related.

CC @golang/release

[bcmills]

But when reporting the actual test times, the total is 0.15 seconds. The latter time probably doesn't include the time that it takes to build the tests, but of course that shouldn't be very long either; on a gomote each takes about 1 second to build.

In #49343, @millerresearch noted that

on the raspberry pi builders each invocation of go tool dist test adds an overhead of >30 seconds, even for a test which takes a small fraction of a second.

Is it possible that that's what's going on here too?

[heschi]

cc @4a6f656c

[millerresearch]

Is it possible that that's what's going on here too?

Yes, although in this case the overhead seems to be about 8 seconds for each invocation of dist test. Still way more than the time taken by the test itself.

The overhead consists mainly of multiple unnecessary calls to checkNotStale, which thrashes the file system on operating systems which don't do as much aggressive caching of directories and inodes as linux does.

The problem is magnified by the unnecessary partitioning of tests into separate invocations of dist test, in many cases only running one test per dist test.

[gopherbot]

Change https://go.dev/cl/384294 mentions this issue: dashboard: allow 60 minutes for 386 OpenBSD builds

[heschi]

Builds are succeeding with a 60-minute timeout. Given the above hypothesis about expensive filesystem reads, this doesn't seem like a release blocker.

[gopherbot]

Change https://go.dev/cl/406216 mentions this issue: cmd/coordinator: consolidate and increase global VM deletion timeout