Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
bcmills opened this issue Aug 25, 2022 · 9 comments
Closed

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

bcmills opened this issue Aug 25, 2022 · 9 comments
Assignees
Labels
Builders x/build issues (builders, bots, dashboards) FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@bcmills
Copy link
Contributor

bcmills commented Aug 25, 2022

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)

@gopherbot gopherbot added the Builders x/build issues (builders, bots, dashboards) label Aug 25, 2022
@gopherbot gopherbot added this to the Unreleased milestone Aug 25, 2022
@bcmills bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Aug 25, 2022
@prattmic
Copy link
Member

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
Copy link
Member

prattmic commented Aug 25, 2022

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).

@heschi heschi added this to Planned in Go Release Team Aug 30, 2022
@gopherbot
Copy link

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

gopherbot pushed a commit to golang/build that referenced this issue Nov 28, 2022
This change replaces linux-arm64-aws with linux-arm64. The new builder runs
on GCP and has an increased set of resources. This should provide a
performance improvement.

The builder will now be used:
- To release linux-arm64
- As the linux-arm64 trybot

Fixes golang/go#53851
Updates golang/go#54679
Updates golang/go#40561

Change-Id: I9abfe2ed1d1bd8a68bba1e1f924637e829026e6d
Reviewed-on: https://go-review.googlesource.com/c/build/+/449615
Reviewed-by: Dmitri Shuralyov <dmitshur@google.com>
Run-TryBot: Carlos Amedee <carlos@golang.org>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Dmitri Shuralyov <dmitshur@golang.org>
Reviewed-by: Jenny Rakoczy <jenny@golang.org>
@bcmills
Copy link
Contributor Author

bcmills commented Jan 24, 2023

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
Copy link
Contributor Author

bcmills commented Jan 27, 2023

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
Copy link
Contributor Author

bcmills commented Jan 27, 2023

@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
Copy link
Contributor

dmitshur commented Jan 27, 2023

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
Copy link
Contributor

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.

@gopherbot
Copy link

Change https://go.dev/cl/468535 mentions this issue: dashboard: remove linux-arm-aws from trybots

@dmitshur dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Feb 15, 2023
@golang golang locked and limited conversation to collaborators Feb 15, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Builders x/build issues (builders, bots, dashboards) FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
Archived in project
Development

No branches or pull requests

5 participants