x/build: `linux-arm.*-aws` TryBots are often stragglers

[bcmills]

On several CLs lately, I've seen nearly all of the builders complete within 10 minutes or so, but the linux-arm-aws and linux-arm64-aws TryBots always seem to take 15 minutes or more.

It appears that these builders aren't currently sharded at all:
https://cs.opensource.google/go/x/build/+/master:dashboard/builders.go;l=2417;drc=9ca9dc28e477c63197a65122b31a98146c49d07d
https://cs.opensource.google/go/x/build/+/master:dashboard/builders.go;l=2434;drc=9ca9dc28e477c63197a65122b31a98146c49d07d

Is there something we can do to bring the latency for these builders up to par with the other TryBots? (Perhaps enable sharding?)

(CC @prattmic, who I think has done some recent latency measurements)

[prattmic]

I did some measurements a while ago analyzing builds from May 1 - June 10. Paraphrasing the results I found:

Rank (by median)	Builder	Median Total Time (s)	p90 Total Time (s)
1	darwin-arm64-12_0-toothrot	424	1257
...
6	linux-arm64-aws	495	820
...
11	linux-amd64	530	853
...
32	linux-arm-aws	668	1105
...
82	linux-amd64-longtest	2760	3107

Rerunning the analysis since August 1, I get:

Rank (by median)	Builder	Median Total Time (s)	p90 Total Time (s)
1	misc-compile-mips	264	366
...
18	linux-amd64	385	659
...
27	linux-arm64-aws	525	867
...
36	linux-arm-aws	720	1204
...
87	linux-amd64-longtest	2541	2814

I think the main difference is that https://go.dev/cl/419077 changed most GCE builders from 4vCPU/16GB to 16vCPU/64GB instances, significantly speeding them up, but linux-arm{64}-aws are still on 4vCPU/16GB instances (m6g.xlarge).

There is a 16vCPU/64GB instance type available (m6g.4xlarge), which we could potentially switch to.

[prattmic]

These are the post-submit builds, but data is similar for trybots (both arm builders are actually slightly faster in trybots).

That said, this data doesn't seem to match your observation "linux-arm-aws and linux-arm64-aws TryBots always seem to take 15 minutes or more." For linux-arm64-aws, even the p90 case is faster than 15 minutes (p99 is 916s). Maybe something is missing from analysis (it does include time spent waiting for a buildet, which is ~60s median for both builders).

[gopherbot]

Change https://go.dev/cl/449615 mentions this issue: all: replace linux-arm64-aws with linux-arm64

[bcmills]

I noticed this again on https://farmer.golang.org/try?commit=41ddcbff.
All of the other TryBots and SlowBots (including -longtest builders!) finished, and after 21 minutes linux-arm-aws is still chugging along on ../misc and ../test. 😩

[bcmills]

On https://farmer.golang.org/try?commit=14f8fad9, linux-arm-aws took over 20 minutes.

The next-slowest builder (windows-386-2012) took only 11m20s, and it looks like even that one will go away for #58008.

[bcmills]

@golang/release, if speeding this up isn't a priority at the moment, any chance we could demote the linux-arm-aws builder to a SlowBot in the interim?

[dmitshur]

Here's the event log from the aforementioned 20-minute TryBot run, for reference:

  builder: linux-arm-aws
      rev: 14f8fad9ff9d62970ec629f0f71c3c22ffcee644
 buildlet: https://18.191.240.124 EC2 VM: buildlet-linux-arm-aws-rn8b68f22
  started: 2023-01-27 21:37:50.696622793 +0000 UTC m=+13510.877338546
    ended: 2023-01-27 21:58:57.126526614 +0000 UTC m=+14777.307242353
  success: true

Events:
  2023-01-27T21:37:50Z get_buildlet 
  2023-01-27T21:38:35Z finish_get_buildlet after 44.3s
  2023-01-27T21:38:35Z using_buildlet 18.191.240.124:443
  2023-01-27T21:38:35Z write_go_bootstrap_tar 
  2023-01-27T21:38:35Z write_version_tar 
  2023-01-27T21:38:35Z get_source go@14f8fad9ff9d62970ec629f0f71c3c22ffcee644
  2023-01-27T21:38:35Z finish_get_source after 0s; go@14f8fad9ff9d62970ec629f0f71c3c22ffcee644
  2023-01-27T21:38:35Z write_go_src_tar 
  2023-01-27T21:38:37Z finish_write_go_src_tar after 2.33s
  2023-01-27T21:38:38Z finish_write_go_bootstrap_tar after 2.91s
  2023-01-27T21:38:38Z make_and_test 
  2023-01-27T21:38:38Z make src/make.bash
  2023-01-27T21:40:38Z starting_helpers 
  2023-01-27T21:40:38Z get_helper helper 1/1
  2023-01-27T21:40:54Z finish_get_helper after 16.7s; err=failed waiting for vm instance: failed waiting for vm instance: ResourceNotReady: failed waiting for successful resource state; helper 1/1
  2023-01-27T21:41:23Z finish_make after 2m45.4s; src/make.bash
  2023-01-27T21:41:23Z clean_for_snapshot 
  2023-01-27T21:41:23Z finish_clean_for_snapshot after 28.3ms
  2023-01-27T21:41:23Z write_snapshot_to_gcs 
  2023-01-27T21:41:23Z fetch_snapshot_reader_from_buildlet 
  2023-01-27T21:41:23Z finish_fetch_snapshot_reader_from_buildlet after 75.2ms
  2023-01-27T21:41:28Z finish_write_snapshot_to_gcs after 4.64s
  2023-01-27T21:41:28Z discovering_tests 
  2023-01-27T21:41:28Z get_test_stats 
  2023-01-27T21:41:28Z finish_get_test_stats after 0s
  2023-01-27T21:41:28Z starting_tests 317 tests
  2023-01-27T21:41:29Z run_tests_multi 18.191.240.124:443: [go_test:archive/tar go_test:archive/zip go_test:bufio]
  2023-01-27T21:41:34Z finish_run_tests_multi after 5.33s; 18.191.240.124:443: [go_test:archive/tar go_test:archive/zip go_test:bufio]
  2023-01-27T21:41:34Z run_test:go_test:bytes 18.191.240.124:443
  2023-01-27T21:41:44Z finish_run_test:go_test:bytes after 9.68s; 18.191.240.124:443
  2023-01-27T21:41:44Z run_tests_multi 18.191.240.124:443: [go_test:compress/bzip2 go_test:compress/flate]
  2023-01-27T21:41:48Z finish_run_tests_multi after 4.33s; 18.191.240.124:443: [go_test:compress/bzip2 go_test:compress/flate]
  2023-01-27T21:41:48Z run_test:go_test:compress/gzip 18.191.240.124:443
  2023-01-27T21:42:01Z finish_run_test:go_test:compress/gzip after 12.5s; 18.191.240.124:443
  2023-01-27T21:42:01Z run_tests_multi 18.191.240.124:443: [go_test:compress/lzw go_test:compress/zlib go_test:container/heap]
  2023-01-27T21:42:04Z finish_run_tests_multi after 3.62s; 18.191.240.124:443: [go_test:compress/lzw go_test:compress/zlib go_test:container/heap]
  2023-01-27T21:42:04Z run_tests_multi 18.191.240.124:443: [go_test:container/list go_test:container/ring go_test:context]
  2023-01-27T21:42:10Z finish_run_tests_multi after 5.39s; 18.191.240.124:443: [go_test:container/list go_test:container/ring go_test:context]
  2023-01-27T21:42:10Z run_tests_multi 18.191.240.124:443: [go_test:crypto go_test:crypto/aes go_test:crypto/cipher]
  2023-01-27T21:42:13Z finish_run_tests_multi after 3.5s; 18.191.240.124:443: [go_test:crypto go_test:crypto/aes go_test:crypto/cipher]
  2023-01-27T21:42:13Z run_tests_multi 18.191.240.124:443: [go_test:crypto/des go_test:crypto/dsa go_test:crypto/ecdh]
  2023-01-27T21:42:17Z finish_run_tests_multi after 3.5s; 18.191.240.124:443: [go_test:crypto/des go_test:crypto/dsa go_test:crypto/ecdh]
  2023-01-27T21:42:17Z run_tests_multi 18.191.240.124:443: [go_test:crypto/ecdsa go_test:crypto/ed25519 go_test:crypto/elliptic]
  2023-01-27T21:42:21Z finish_run_tests_multi after 4.23s; 18.191.240.124:443: [go_test:crypto/ecdsa go_test:crypto/ed25519 go_test:crypto/elliptic]
  2023-01-27T21:42:21Z run_tests_multi 18.191.240.124:443: [go_test:crypto/hmac go_test:crypto/internal/alias go_test:crypto/internal/bigmod go_test:crypto/internal/boring]
  2023-01-27T21:42:25Z finish_run_tests_multi after 3.82s; 18.191.240.124:443: [go_test:crypto/hmac go_test:crypto/internal/alias go_test:crypto/internal/bigmod go_test:crypto/internal/boring]
  2023-01-27T21:42:25Z run_test:go_test:crypto/internal/boring/bcache 18.191.240.124:443
  2023-01-27T21:42:28Z finish_run_test:go_test:crypto/internal/boring/bcache after 3.08s; 18.191.240.124:443
  2023-01-27T21:42:28Z run_test:go_test:crypto/internal/edwards25519 18.191.240.124:443
  2023-01-27T21:42:54Z finish_run_test:go_test:crypto/internal/edwards25519 after 25.8s; 18.191.240.124:443
  2023-01-27T21:42:54Z run_test:go_test:crypto/internal/edwards25519/field 18.191.240.124:443
  2023-01-27T21:43:21Z finish_run_test:go_test:crypto/internal/edwards25519/field after 26.6s; 18.191.240.124:443
  2023-01-27T21:43:21Z run_test:go_test:crypto/internal/nistec 18.191.240.124:443
  2023-01-27T21:43:30Z finish_run_test:go_test:crypto/internal/nistec after 9.75s; 18.191.240.124:443
  2023-01-27T21:43:30Z run_tests_multi 18.191.240.124:443: [go_test:crypto/internal/nistec/fiat go_test:crypto/md5 go_test:crypto/rand go_test:crypto/rc4 go_test:crypto/rsa go_test:crypto/sha1 go_test:crypto/sha256 go_test:crypto/sha512 go_test:crypto/subtle]
  2023-01-27T21:43:36Z finish_run_tests_multi after 5.23s; 18.191.240.124:443: [go_test:crypto/internal/nistec/fiat go_test:crypto/md5 go_test:crypto/rand go_test:crypto/rc4 go_test:crypto/rsa go_test:crypto/sha1 go_test:crypto/sha256 go_test:crypto/sha512 go_test:crypto/subtle]
  2023-01-27T21:43:36Z run_test:go_test:crypto/tls 18.191.240.124:443
  2023-01-27T21:43:45Z finish_run_test:go_test:crypto/tls after 9.17s; 18.191.240.124:443
  2023-01-27T21:43:45Z run_tests_multi 18.191.240.124:443: [go_test:crypto/x509 go_test:database/sql]
  2023-01-27T21:43:54Z finish_run_tests_multi after 8.75s; 18.191.240.124:443: [go_test:crypto/x509 go_test:database/sql]
  2023-01-27T21:43:54Z run_tests_multi 18.191.240.124:443: [go_test:database/sql/driver go_test:debug/buildinfo go_test:debug/dwarf go_test:debug/elf go_test:debug/gosym go_test:debug/macho go_test:debug/pe go_test:debug/plan9obj go_test:embed go_test:embed/internal/embedtest go_test:encoding/ascii85 go_test:encoding/asn1 go_test:encoding/base32]
  2023-01-27T21:43:59Z finish_run_tests_multi after 5.59s; 18.191.240.124:443: [go_test:database/sql/driver go_test:debug/buildinfo go_test:debug/dwarf go_test:debug/elf go_test:debug/gosym go_test:debug/macho go_test:debug/pe go_test:debug/plan9obj go_test:embed go_test:embed/internal/embedtest go_test:encoding/ascii85 go_test:encoding/asn1 go_test:encoding/base32]
  2023-01-27T21:43:59Z run_tests_multi 18.191.240.124:443: [go_test:encoding/base64 go_test:encoding/binary go_test:encoding/csv go_test:encoding/gob go_test:encoding/hex go_test:encoding/json]
  2023-01-27T21:44:07Z finish_run_tests_multi after 7.2s; 18.191.240.124:443: [go_test:encoding/base64 go_test:encoding/binary go_test:encoding/csv go_test:encoding/gob go_test:encoding/hex go_test:encoding/json]
  2023-01-27T21:44:07Z run_tests_multi 18.191.240.124:443: [go_test:encoding/pem go_test:encoding/xml go_test:errors go_test:expvar go_test:flag go_test:fmt go_test:go/ast]
  2023-01-27T21:44:14Z finish_run_tests_multi after 7.14s; 18.191.240.124:443: [go_test:encoding/pem go_test:encoding/xml go_test:errors go_test:expvar go_test:flag go_test:fmt go_test:go/ast]
  2023-01-27T21:44:14Z run_tests_multi 18.191.240.124:443: [go_test:go/build go_test:go/build/constraint go_test:go/constant go_test:go/doc go_test:go/doc/comment go_test:go/format go_test:go/importer go_test:go/internal/gccgoimporter]
  2023-01-27T21:44:21Z finish_run_tests_multi after 6.61s; 18.191.240.124:443: [go_test:go/build go_test:go/build/constraint go_test:go/constant go_test:go/doc go_test:go/doc/comment go_test:go/format go_test:go/importer go_test:go/internal/gccgoimporter]
  2023-01-27T21:44:21Z run_test:go_test:go/internal/gcimporter 18.191.240.124:443
  2023-01-27T21:44:25Z finish_run_test:go_test:go/internal/gcimporter after 4.13s; 18.191.240.124:443
  2023-01-27T21:44:25Z run_test:go_test:go/internal/srcimporter 18.191.240.124:443
  2023-01-27T21:44:35Z finish_run_test:go_test:go/internal/srcimporter after 10.6s; 18.191.240.124:443
  2023-01-27T21:44:35Z run_tests_multi 18.191.240.124:443: [go_test:go/parser go_test:go/printer go_test:go/scanner go_test:go/token]
  2023-01-27T21:44:41Z finish_run_tests_multi after 5.04s; 18.191.240.124:443: [go_test:go/parser go_test:go/printer go_test:go/scanner go_test:go/token]
  2023-01-27T21:44:41Z run_test:go_test:go/types 18.191.240.124:443
  2023-01-27T21:44:55Z finish_run_test:go_test:go/types after 14s; 18.191.240.124:443
  2023-01-27T21:44:55Z run_tests_multi 18.191.240.124:443: [go_test:hash go_test:hash/adler32 go_test:hash/crc32 go_test:hash/crc64 go_test:hash/fnv go_test:hash/maphash go_test:html go_test:html/template go_test:image go_test:image/color go_test:image/draw go_test:image/gif]
  2023-01-27T21:45:00Z finish_run_tests_multi after 5.59s; 18.191.240.124:443: [go_test:hash go_test:hash/adler32 go_test:hash/crc32 go_test:hash/crc64 go_test:hash/fnv go_test:hash/maphash go_test:html go_test:html/template go_test:image go_test:image/color go_test:image/draw go_test:image/gif]
  2023-01-27T21:45:00Z run_tests_multi 18.191.240.124:443: [go_test:image/jpeg go_test:image/png go_test:index/suffixarray]
  2023-01-27T21:45:05Z finish_run_tests_multi after 4.57s; 18.191.240.124:443: [go_test:image/jpeg go_test:image/png go_test:index/suffixarray]
  2023-01-27T21:45:05Z run_test:go_test:internal/abi 18.191.240.124:443
  2023-01-27T21:45:20Z finish_run_test:go_test:internal/abi after 15.2s; 18.191.240.124:443
  2023-01-27T21:45:20Z run_tests_multi 18.191.240.124:443: [go_test:internal/buildcfg go_test:internal/coverage/cformat go_test:internal/coverage/cmerge go_test:internal/coverage/pods go_test:internal/coverage/slicereader go_test:internal/coverage/slicewriter go_test:internal/coverage/test]
  2023-01-27T21:45:24Z finish_run_tests_multi after 3.45s; 18.191.240.124:443: [go_test:internal/buildcfg go_test:internal/coverage/cformat go_test:internal/coverage/cmerge go_test:internal/coverage/pods go_test:internal/coverage/slicereader go_test:internal/coverage/slicewriter go_test:internal/coverage/test]
  2023-01-27T21:45:24Z run_test:go_test:internal/cpu 18.191.240.124:443
  2023-01-27T21:45:34Z finish_run_test:go_test:internal/cpu after 10.2s; 18.191.240.124:443
  2023-01-27T21:45:34Z run_tests_multi 18.191.240.124:443: [go_test:internal/dag go_test:internal/diff go_test:internal/fmtsort go_test:internal/fuzz go_test:internal/godebug go_test:internal/intern go_test:internal/itoa go_test:internal/poll]
  2023-01-27T21:45:42Z finish_run_tests_multi after 8.2s; 18.191.240.124:443: [go_test:internal/dag go_test:internal/diff go_test:internal/fmtsort go_test:internal/fuzz go_test:internal/godebug go_test:internal/intern go_test:internal/itoa go_test:internal/poll]
  2023-01-27T21:45:42Z run_tests_multi 18.191.240.124:443: [go_test:internal/profile go_test:internal/reflectlite go_test:internal/safefilepath go_test:internal/saferio go_test:internal/singleflight go_test:internal/testenv go_test:internal/trace go_test:internal/types/errors go_test:internal/unsafeheader]
  2023-01-27T21:45:50Z finish_run_tests_multi after 8s; 18.191.240.124:443: [go_test:internal/profile go_test:internal/reflectlite go_test:internal/safefilepath go_test:internal/saferio go_test:internal/singleflight go_test:internal/testenv go_test:internal/trace go_test:internal/types/errors go_test:internal/unsafeheader]
  2023-01-27T21:45:50Z run_tests_multi 18.191.240.124:443: [go_test:internal/xcoff go_test:io go_test:io/fs go_test:io/ioutil go_test:log go_test:log/syslog]
  2023-01-27T21:45:57Z finish_run_tests_multi after 7.39s; 18.191.240.124:443: [go_test:internal/xcoff go_test:io go_test:io/fs go_test:io/ioutil go_test:log go_test:log/syslog]
  2023-01-27T21:45:57Z run_test:go_test:math 18.191.240.124:443
  2023-01-27T21:46:04Z finish_run_test:go_test:math after 6.08s; 18.191.240.124:443
  2023-01-27T21:46:04Z run_tests_multi 18.191.240.124:443: [go_test:math/big go_test:math/bits go_test:math/cmplx go_test:math/rand]
  2023-01-27T21:46:12Z finish_run_tests_multi after 8.42s; 18.191.240.124:443: [go_test:math/big go_test:math/bits go_test:math/cmplx go_test:math/rand]
  2023-01-27T21:46:12Z run_tests_multi 18.191.240.124:443: [go_test:mime go_test:mime/multipart go_test:mime/quotedprintable]
  2023-01-27T21:46:16Z finish_run_tests_multi after 3.63s; 18.191.240.124:443: [go_test:mime go_test:mime/multipart go_test:mime/quotedprintable]
  2023-01-27T21:46:16Z run_test:go_test:net 18.191.240.124:443
  2023-01-27T21:46:33Z finish_run_test:go_test:net after 16.8s; 18.191.240.124:443
  2023-01-27T21:46:33Z run_test:go_test:net/http 18.191.240.124:443
  2023-01-27T21:46:57Z finish_run_test:go_test:net/http after 24.5s; 18.191.240.124:443
  2023-01-27T21:46:57Z run_tests_multi 18.191.240.124:443: [go_test:net/http/cgi go_test:net/http/cookiejar go_test:net/http/fcgi go_test:net/http/httptest go_test:net/http/httptrace go_test:net/http/httputil go_test:net/http/internal go_test:net/http/internal/ascii]
  2023-01-27T21:47:04Z finish_run_tests_multi after 6.99s; 18.191.240.124:443: [go_test:net/http/cgi go_test:net/http/cookiejar go_test:net/http/fcgi go_test:net/http/httptest go_test:net/http/httptrace go_test:net/http/httputil go_test:net/http/internal go_test:net/http/internal/ascii]
  2023-01-27T21:47:04Z run_tests_multi 18.191.240.124:443: [go_test:net/http/pprof go_test:net/internal/socktest go_test:net/mail go_test:net/netip]
  2023-01-27T21:47:12Z finish_run_tests_multi after 7.5s; 18.191.240.124:443: [go_test:net/http/pprof go_test:net/internal/socktest go_test:net/mail go_test:net/netip]
  2023-01-27T21:47:12Z run_tests_multi 18.191.240.124:443: [go_test:net/rpc go_test:net/rpc/jsonrpc go_test:net/smtp go_test:net/textproto go_test:net/url go_test:os go_test:os/exec]
  2023-01-27T21:47:19Z finish_run_tests_multi after 7.48s; 18.191.240.124:443: [go_test:net/rpc go_test:net/rpc/jsonrpc go_test:net/smtp go_test:net/textproto go_test:net/url go_test:os go_test:os/exec]
  2023-01-27T21:47:19Z run_tests_multi 18.191.240.124:443: [go_test:os/exec/internal/fdtest go_test:os/signal go_test:os/user go_test:path go_test:path/filepath go_test:plugin]
  2023-01-27T21:47:26Z finish_run_tests_multi after 6.94s; 18.191.240.124:443: [go_test:os/exec/internal/fdtest go_test:os/signal go_test:os/user go_test:path go_test:path/filepath go_test:plugin]
  2023-01-27T21:47:26Z run_tests_multi 18.191.240.124:443: [go_test:reflect go_test:regexp]
  2023-01-27T21:47:34Z finish_run_tests_multi after 7.65s; 18.191.240.124:443: [go_test:reflect go_test:regexp]
  2023-01-27T21:47:34Z run_test:go_test:regexp/syntax 18.191.240.124:443
  2023-01-27T21:47:38Z finish_run_test:go_test:regexp/syntax after 4.28s; 18.191.240.124:443
  2023-01-27T21:47:38Z run_test:go_test:runtime 18.191.240.124:443
  2023-01-27T21:48:08Z still_waiting_on_test go_test:runtime
  2023-01-27T21:48:20Z finish_run_test:go_test:runtime after 42s; 18.191.240.124:443
  2023-01-27T21:48:20Z run_tests_multi 18.191.240.124:443: [go_test:runtime/cgo go_test:runtime/coverage go_test:runtime/debug go_test:runtime/internal/atomic go_test:runtime/internal/math go_test:runtime/internal/sys go_test:runtime/internal/syscall go_test:runtime/metrics]
  2023-01-27T21:48:25Z finish_run_tests_multi after 4.01s; 18.191.240.124:443: [go_test:runtime/cgo go_test:runtime/coverage go_test:runtime/debug go_test:runtime/internal/atomic go_test:runtime/internal/math go_test:runtime/internal/sys go_test:runtime/internal/syscall go_test:runtime/metrics]
  2023-01-27T21:48:25Z run_test:go_test:runtime/pprof 18.191.240.124:443
  2023-01-27T21:48:34Z finish_run_test:go_test:runtime/pprof after 9.03s; 18.191.240.124:443
  2023-01-27T21:48:34Z run_tests_multi 18.191.240.124:443: [go_test:runtime/trace go_test:sort]
  2023-01-27T21:48:39Z finish_run_tests_multi after 5.61s; 18.191.240.124:443: [go_test:runtime/trace go_test:sort]
  2023-01-27T21:48:39Z run_test:go_test:strconv 18.191.240.124:443
  2023-01-27T21:48:46Z finish_run_test:go_test:strconv after 6.29s; 18.191.240.124:443
  2023-01-27T21:48:46Z run_test:go_test:strings 18.191.240.124:443
  2023-01-27T21:48:55Z finish_run_test:go_test:strings after 9.15s; 18.191.240.124:443
  2023-01-27T21:48:55Z run_test:go_test:sync 18.191.240.124:443
  2023-01-27T21:49:02Z finish_run_test:go_test:sync after 7.15s; 18.191.240.124:443
  2023-01-27T21:49:02Z run_tests_multi 18.191.240.124:443: [go_test:sync/atomic go_test:syscall]
  2023-01-27T21:49:11Z finish_run_tests_multi after 8.99s; 18.191.240.124:443: [go_test:sync/atomic go_test:syscall]
  2023-01-27T21:49:11Z run_tests_multi 18.191.240.124:443: [go_test:testing go_test:testing/fstest go_test:testing/iotest go_test:testing/quick go_test:text/scanner go_test:text/tabwriter go_test:text/template go_test:text/template/parse]
  2023-01-27T21:49:16Z finish_run_tests_multi after 5.21s; 18.191.240.124:443: [go_test:testing go_test:testing/fstest go_test:testing/iotest go_test:testing/quick go_test:text/scanner go_test:text/tabwriter go_test:text/template go_test:text/template/parse]
  2023-01-27T21:49:16Z run_tests_multi 18.191.240.124:443: [go_test:time go_test:unicode go_test:unicode/utf16]
  2023-01-27T21:49:25Z finish_run_tests_multi after 8.61s; 18.191.240.124:443: [go_test:time go_test:unicode go_test:unicode/utf16]
  2023-01-27T21:49:25Z run_tests_multi 18.191.240.124:443: [go_test:unicode/utf8 go_test:cmd/addr2line]
  2023-01-27T21:49:29Z finish_run_tests_multi after 3.85s; 18.191.240.124:443: [go_test:unicode/utf8 go_test:cmd/addr2line]
  2023-01-27T21:49:29Z run_test:go_test:cmd/api 18.191.240.124:443
  2023-01-27T21:49:40Z finish_run_test:go_test:cmd/api after 11s; 18.191.240.124:443
  2023-01-27T21:49:40Z run_tests_multi 18.191.240.124:443: [go_test:cmd/asm/internal/asm go_test:cmd/asm/internal/lex go_test:cmd/compile/internal/abt go_test:cmd/compile/internal/amd64 go_test:cmd/compile/internal/base go_test:cmd/compile/internal/compare go_test:cmd/compile/internal/dwarfgen go_test:cmd/compile/internal/importer]
  2023-01-27T21:49:49Z finish_run_tests_multi after 9.23s; 18.191.240.124:443: [go_test:cmd/asm/internal/asm go_test:cmd/asm/internal/lex go_test:cmd/compile/internal/abt go_test:cmd/compile/internal/amd64 go_test:cmd/compile/internal/base go_test:cmd/compile/internal/compare go_test:cmd/compile/internal/dwarfgen go_test:cmd/compile/internal/importer]
  2023-01-27T21:49:49Z run_tests_multi 18.191.240.124:443: [go_test:cmd/compile/internal/ir go_test:cmd/compile/internal/logopt go_test:cmd/compile/internal/noder go_test:cmd/compile/internal/reflectdata]
  2023-01-27T21:49:54Z finish_run_tests_multi after 5.03s; 18.191.240.124:443: [go_test:cmd/compile/internal/ir go_test:cmd/compile/internal/logopt go_test:cmd/compile/internal/noder go_test:cmd/compile/internal/reflectdata]
  2023-01-27T21:49:54Z run_test:go_test:cmd/compile/internal/ssa 18.191.240.124:443
  2023-01-27T21:50:24Z still_waiting_on_test go_test:cmd/compile/internal/ssa
  2023-01-27T21:50:25Z finish_run_test:go_test:cmd/compile/internal/ssa after 30.9s; 18.191.240.124:443
  2023-01-27T21:50:25Z run_test:go_test:cmd/compile/internal/syntax 18.191.240.124:443
  2023-01-27T21:50:29Z finish_run_test:go_test:cmd/compile/internal/syntax after 3.77s; 18.191.240.124:443
  2023-01-27T21:50:29Z run_test:go_test:cmd/compile/internal/test 18.191.240.124:443
  2023-01-27T21:50:51Z finish_run_test:go_test:cmd/compile/internal/test after 22.1s; 18.191.240.124:443
  2023-01-27T21:50:51Z run_tests_multi 18.191.240.124:443: [go_test:cmd/compile/internal/typecheck go_test:cmd/compile/internal/types]
  2023-01-27T21:50:56Z finish_run_tests_multi after 4.11s; 18.191.240.124:443: [go_test:cmd/compile/internal/typecheck go_test:cmd/compile/internal/types]
  2023-01-27T21:50:56Z run_test:go_test:cmd/compile/internal/types2 18.191.240.124:443
  2023-01-27T21:51:06Z finish_run_test:go_test:cmd/compile/internal/types2 after 10.6s; 18.191.240.124:443
  2023-01-27T21:51:06Z run_tests_multi 18.191.240.124:443: [go_test:cmd/covdata go_test:cmd/cover go_test:cmd/dist go_test:cmd/doc go_test:cmd/fix go_test:cmd/go]
  2023-01-27T21:51:14Z finish_run_tests_multi after 8.05s; 18.191.240.124:443: [go_test:cmd/covdata go_test:cmd/cover go_test:cmd/dist go_test:cmd/doc go_test:cmd/fix go_test:cmd/go]
  2023-01-27T21:51:14Z run_tests_multi 18.191.240.124:443: [go_test:cmd/go/internal/auth go_test:cmd/go/internal/cache go_test:cmd/go/internal/fsys go_test:cmd/go/internal/generate go_test:cmd/go/internal/get go_test:cmd/go/internal/imports go_test:cmd/go/internal/load go_test:cmd/go/internal/lockedfile go_test:cmd/go/internal/lockedfile/internal/filelock go_test:cmd/go/internal/modconv go_test:cmd/go/internal/modfetch]
  2023-01-27T21:51:20Z finish_run_tests_multi after 5.52s; 18.191.240.124:443: [go_test:cmd/go/internal/auth go_test:cmd/go/internal/cache go_test:cmd/go/internal/fsys go_test:cmd/go/internal/generate go_test:cmd/go/internal/get go_test:cmd/go/internal/imports go_test:cmd/go/internal/load go_test:cmd/go/internal/lockedfile go_test:cmd/go/internal/lockedfile/internal/filelock go_test:cmd/go/internal/modconv go_test:cmd/go/internal/modfetch]
  2023-01-27T21:51:20Z run_tests_multi 18.191.240.124:443: [go_test:cmd/go/internal/modfetch/codehost go_test:cmd/go/internal/modfetch/zip_sum_test go_test:cmd/go/internal/modindex go_test:cmd/go/internal/modload go_test:cmd/go/internal/mvs go_test:cmd/go/internal/par go_test:cmd/go/internal/str go_test:cmd/go/internal/test go_test:cmd/go/internal/vcs go_test:cmd/go/internal/vcweb]
  2023-01-27T21:51:26Z finish_run_tests_multi after 5.82s; 18.191.240.124:443: [go_test:cmd/go/internal/modfetch/codehost go_test:cmd/go/internal/modfetch/zip_sum_test go_test:cmd/go/internal/modindex go_test:cmd/go/internal/modload go_test:cmd/go/internal/mvs go_test:cmd/go/internal/par go_test:cmd/go/internal/str go_test:cmd/go/internal/test go_test:cmd/go/internal/vcs go_test:cmd/go/internal/vcweb]
  2023-01-27T21:51:26Z run_tests_multi 18.191.240.124:443: [go_test:cmd/go/internal/vcweb/vcstest go_test:cmd/go/internal/web go_test:cmd/go/internal/work go_test:cmd/gofmt go_test:cmd/internal/archive go_test:cmd/internal/buildid go_test:cmd/internal/dwarf]
  2023-01-27T21:51:32Z finish_run_tests_multi after 5.69s; 18.191.240.124:443: [go_test:cmd/go/internal/vcweb/vcstest go_test:cmd/go/internal/web go_test:cmd/go/internal/work go_test:cmd/gofmt go_test:cmd/internal/archive go_test:cmd/internal/buildid go_test:cmd/internal/dwarf]
  2023-01-27T21:51:32Z run_tests_multi 18.191.240.124:443: [go_test:cmd/internal/edit go_test:cmd/internal/goobj go_test:cmd/internal/moddeps go_test:cmd/internal/notsha256 go_test:cmd/internal/obj go_test:cmd/internal/obj/ppc64 go_test:cmd/internal/obj/riscv go_test:cmd/internal/obj/s390x]
  2023-01-27T21:51:37Z finish_run_tests_multi after 5.48s; 18.191.240.124:443: [go_test:cmd/internal/edit go_test:cmd/internal/goobj go_test:cmd/internal/moddeps go_test:cmd/internal/notsha256 go_test:cmd/internal/obj go_test:cmd/internal/obj/ppc64 go_test:cmd/internal/obj/riscv go_test:cmd/internal/obj/s390x]
  2023-01-27T21:51:37Z run_tests_multi 18.191.240.124:443: [go_test:cmd/internal/obj/x86 go_test:cmd/internal/objabi go_test:cmd/internal/pkgpath go_test:cmd/internal/pkgpattern go_test:cmd/internal/quoted go_test:cmd/internal/src go_test:cmd/internal/test2json]
  2023-01-27T21:51:45Z finish_run_tests_multi after 7.79s; 18.191.240.124:443: [go_test:cmd/internal/obj/x86 go_test:cmd/internal/objabi go_test:cmd/internal/pkgpath go_test:cmd/internal/pkgpattern go_test:cmd/internal/quoted go_test:cmd/internal/src go_test:cmd/internal/test2json]
  2023-01-27T21:51:45Z run_test:go_test:cmd/link 18.191.240.124:443
  2023-01-27T21:52:04Z finish_run_test:go_test:cmd/link after 18.8s; 18.191.240.124:443
  2023-01-27T21:52:04Z run_test:go_test:cmd/link/internal/benchmark 18.191.240.124:443
  2023-01-27T21:52:07Z finish_run_test:go_test:cmd/link/internal/benchmark after 3.01s; 18.191.240.124:443
  2023-01-27T21:52:07Z run_test:go_test:cmd/link/internal/ld 18.191.240.124:443
  2023-01-27T21:52:16Z finish_run_test:go_test:cmd/link/internal/ld after 8.91s; 18.191.240.124:443
  2023-01-27T21:52:16Z run_tests_multi 18.191.240.124:443: [go_test:cmd/link/internal/loader go_test:cmd/nm]
  2023-01-27T21:52:20Z finish_run_tests_multi after 4.17s; 18.191.240.124:443: [go_test:cmd/link/internal/loader go_test:cmd/nm]
  2023-01-27T21:52:20Z run_tests_multi 18.191.240.124:443: [go_test:cmd/objdump go_test:cmd/pack]
  2023-01-27T21:52:26Z finish_run_tests_multi after 5.58s; 18.191.240.124:443: [go_test:cmd/objdump go_test:cmd/pack]
  2023-01-27T21:52:26Z run_tests_multi 18.191.240.124:443: [go_test:cmd/pprof go_test:cmd/trace]
  2023-01-27T21:52:31Z finish_run_tests_multi after 5.24s; 18.191.240.124:443: [go_test:cmd/pprof go_test:cmd/trace]
  2023-01-27T21:52:31Z run_test:go_test:cmd/vet 18.191.240.124:443
  2023-01-27T21:52:42Z finish_run_test:go_test:cmd/vet after 10.9s; 18.191.240.124:443
  2023-01-27T21:52:42Z run_test:osusergo 18.191.240.124:443
  2023-01-27T21:52:45Z finish_run_test:osusergo after 2.99s; 18.191.240.124:443
  2023-01-27T21:52:45Z run_test:runtime:cpu124 18.191.240.124:443
  2023-01-27T21:53:15Z still_waiting_on_test runtime:cpu124
  2023-01-27T21:53:17Z finish_run_test:runtime:cpu124 after 32s; 18.191.240.124:443
  2023-01-27T21:53:17Z run_test:moved_goroot 18.191.240.124:443
  2023-01-27T21:53:20Z finish_run_test:moved_goroot after 3.32s; 18.191.240.124:443
  2023-01-27T21:53:20Z run_test:sync_cpu 18.191.240.124:443
  2023-01-27T21:53:24Z finish_run_test:sync_cpu after 3.38s; 18.191.240.124:443
  2023-01-27T21:53:24Z run_test:cgo_stdio 18.191.240.124:443
  2023-01-27T21:53:29Z finish_run_test:cgo_stdio after 4.65s; 18.191.240.124:443
  2023-01-27T21:53:29Z run_test:cgo_life 18.191.240.124:443
  2023-01-27T21:53:33Z finish_run_test:cgo_life after 4.19s; 18.191.240.124:443
  2023-01-27T21:53:33Z run_test:cgo_fortran 18.191.240.124:443
  2023-01-27T21:53:36Z finish_run_test:cgo_fortran after 3.09s; 18.191.240.124:443
  2023-01-27T21:53:36Z run_test:cgo:test-auto 18.191.240.124:443
  2023-01-27T21:53:46Z finish_run_test:cgo:test-auto after 9.94s; 18.191.240.124:443
  2023-01-27T21:53:46Z run_test:cgo:test-internal 18.191.240.124:443
  2023-01-27T21:53:50Z finish_run_test:cgo:test-internal after 4.09s; 18.191.240.124:443
  2023-01-27T21:53:50Z run_test:cgo:test-external-g0 18.191.240.124:443
  2023-01-27T21:54:01Z finish_run_test:cgo:test-external-g0 after 10.3s; 18.191.240.124:443
  2023-01-27T21:54:01Z run_test:cgo:testtls-auto 18.191.240.124:443
  2023-01-27T21:54:04Z finish_run_test:cgo:testtls-auto after 3.27s; 18.191.240.124:443
  2023-01-27T21:54:04Z run_test:cgo:testtls-external 18.191.240.124:443
  2023-01-27T21:54:07Z finish_run_test:cgo:testtls-external after 3.06s; 18.191.240.124:443
  2023-01-27T21:54:07Z run_test:cgo:testtls-static 18.191.240.124:443
  2023-01-27T21:54:10Z finish_run_test:cgo:testtls-static after 3.08s; 18.191.240.124:443
  2023-01-27T21:54:10Z run_test:cgo:nocgo-auto 18.191.240.124:443
  2023-01-27T21:54:13Z finish_run_test:cgo:nocgo-auto after 2.94s; 18.191.240.124:443
  2023-01-27T21:54:13Z run_test:cgo:nocgo-external 18.191.240.124:443
  2023-01-27T21:54:16Z finish_run_test:cgo:nocgo-external after 3.09s; 18.191.240.124:443
  2023-01-27T21:54:16Z run_test:cgo:nocgo-static 18.191.240.124:443
  2023-01-27T21:54:19Z finish_run_test:cgo:nocgo-static after 3.13s; 18.191.240.124:443
  2023-01-27T21:54:19Z run_test:cgo:test-static 18.191.240.124:443
  2023-01-27T21:54:28Z finish_run_test:cgo:test-static after 8.78s; 18.191.240.124:443
  2023-01-27T21:54:28Z run_test:cgo:test-static-env 18.191.240.124:443
  2023-01-27T21:54:39Z finish_run_test:cgo:test-static-env after 10.2s; 18.191.240.124:443
  2023-01-27T21:54:39Z run_test:cgo:test-pie 18.191.240.124:443
  2023-01-27T21:54:51Z finish_run_test:cgo:test-pie after 12.4s; 18.191.240.124:443
  2023-01-27T21:54:51Z run_test:cgo:testtls-pie 18.191.240.124:443
  2023-01-27T21:54:54Z finish_run_test:cgo:testtls-pie after 3.22s; 18.191.240.124:443
  2023-01-27T21:54:54Z run_test:cgo:nocgo-pie 18.191.240.124:443
  2023-01-27T21:54:57Z finish_run_test:cgo:nocgo-pie after 3.1s; 18.191.240.124:443
  2023-01-27T21:54:57Z run_test:testgodefs 18.191.240.124:443
  2023-01-27T21:55:01Z finish_run_test:testgodefs after 3.54s; 18.191.240.124:443
  2023-01-27T21:55:01Z run_test:testso 18.191.240.124:443
  2023-01-27T21:55:05Z finish_run_test:testso after 3.59s; 18.191.240.124:443
  2023-01-27T21:55:05Z run_test:testsovar 18.191.240.124:443
  2023-01-27T21:55:08Z finish_run_test:testsovar after 3.64s; 18.191.240.124:443
  2023-01-27T21:55:08Z run_test:testcshared 18.191.240.124:443
  2023-01-27T21:55:15Z finish_run_test:testcshared after 6.99s; 18.191.240.124:443
  2023-01-27T21:55:15Z run_test:testshared 18.191.240.124:443
  2023-01-27T21:55:45Z still_waiting_on_test testshared
  2023-01-27T21:56:00Z finish_run_test:testshared after 44.9s; 18.191.240.124:443
  2023-01-27T21:56:00Z run_test:testplugin 18.191.240.124:443
  2023-01-27T21:56:25Z finish_run_test:testplugin after 24.4s; 18.191.240.124:443
  2023-01-27T21:56:25Z run_test:testsanitizers 18.191.240.124:443
  2023-01-27T21:56:28Z finish_run_test:testsanitizers after 3.24s; 18.191.240.124:443
  2023-01-27T21:56:28Z run_test:cgo_errors 18.191.240.124:443
  2023-01-27T21:56:35Z finish_run_test:cgo_errors after 6.81s; 18.191.240.124:443
  2023-01-27T21:56:35Z run_test:bench_go1 18.191.240.124:443
  2023-01-27T21:56:39Z finish_run_test:bench_go1 after 3.5s; 18.191.240.124:443
  2023-01-27T21:56:39Z run_test:test:0_10 18.191.240.124:443
  2023-01-27T21:56:56Z finish_run_test:test:0_10 after 17.4s; 18.191.240.124:443
  2023-01-27T21:56:56Z run_test:test:1_10 18.191.240.124:443
  2023-01-27T21:57:12Z finish_run_test:test:1_10 after 15.9s; 18.191.240.124:443
  2023-01-27T21:57:12Z run_test:test:2_10 18.191.240.124:443
  2023-01-27T21:57:25Z finish_run_test:test:2_10 after 12.6s; 18.191.240.124:443
  2023-01-27T21:57:25Z run_test:test:3_10 18.191.240.124:443
  2023-01-27T21:57:36Z finish_run_test:test:3_10 after 11.6s; 18.191.240.124:443
  2023-01-27T21:57:36Z run_test:test:4_10 18.191.240.124:443
  2023-01-27T21:57:53Z finish_run_test:test:4_10 after 17.1s; 18.191.240.124:443
  2023-01-27T21:57:53Z run_test:test:5_10 18.191.240.124:443
  2023-01-27T21:58:05Z finish_run_test:test:5_10 after 11.1s; 18.191.240.124:443
  2023-01-27T21:58:05Z run_test:test:6_10 18.191.240.124:443
  2023-01-27T21:58:17Z finish_run_test:test:6_10 after 12.2s; 18.191.240.124:443
  2023-01-27T21:58:17Z run_test:test:7_10 18.191.240.124:443
  2023-01-27T21:58:28Z finish_run_test:test:7_10 after 11.3s; 18.191.240.124:443
  2023-01-27T21:58:28Z run_test:test:8_10 18.191.240.124:443
  2023-01-27T21:58:43Z finish_run_test:test:8_10 after 14.3s; 18.191.240.124:443
  2023-01-27T21:58:43Z run_test:test:9_10 18.191.240.124:443
  2023-01-27T21:58:53Z finish_run_test:test:9_10 after 10.7s; 18.191.240.124:443
  2023-01-27T21:58:53Z run_test:reboot 18.191.240.124:443
  2023-01-27T21:58:57Z finish_run_test:reboot after 3.11s; 18.191.240.124:443
  2023-01-27T21:58:57Z tests_complete took 17m28.067570639s; aggregate 17m21.105450927s; saved -6.962119712s
  2023-01-27T21:58:57Z finish_make_and_test after 20m18.9s
  2023-01-27T21:58:57Z done all tests passed

There's no one particular thing that's slow, it just takes 20 minutes to get through everything. The "saved -7 seconds" part in the summary stands out:

tests_complete took 17m28.067570639s; aggregate 17m21.105450927s; saved -6.962119712s

The builder is configured to have 1 try-helper, so its execution should be sharded across 2 instances. However, it seems it failed to get the helper due to "ResourceNotReady" and so it ran everything on the one instance (hence there was no time saved above):

starting_helpers 
get_helper helper 1/1
finish_get_helper after 16.7s; err=failed waiting for vm instance: failed waiting for vm instance: ResourceNotReady: failed waiting for successful resource state; helper 1/1

---

If the builder is so slow that having it be a post-submit builder only is more helpful than having it as a trybot, making that change for now seems reasonable to me. It would be replaced by a misc-compile trybot that would provide bare minimum coverage.

[cagedmantis]

A couple of thoughts about this:

• I have not been able to reproduce a run taking this long via debugvm.
• Switching to the m6g.2xlarge machine type shaves off a quarter of the observed build time.
• The ResourceNotReady error is happening after 16.7s. Add that to the 44.3s seconds that it took to get the main buildlet and that seems like there is a 60 second limit for both. Thats a clear problem.

For the time being, the post-submit builder route seems like the right call.