x/build: freebsd-amd64-10_3 trybot took over 20 minutes

[dmitshur]

From https://go-review.googlesource.com/c/go/+/214079/1#message-7f31aa619ce56c7e7101472dd62cdc6402837b34, a CL on release-branch.go1.12 branch, the freebsd-amd64-10_3 builder took 23~ minutes. All others finished in 10 minutes or under.

Need to investigate if this happens consistently, because 20+ minutes is way longer than the goal for trybot run time.

/cc @golang/osp-team

[dmitshur]

This was its build log:

  builder: freebsd-amd64-10_3
      rev: 83d7ec855bf73948effea263cb4ee3b2d2474c92
 buildlet: http://10.240.0.155 GCE VM: buildlet-freebsd-10-3-rne510e3d
  started: 2020-01-09 15:58:47.222007117 +0000 UTC m=+174703.578319757
   status: still running

Events:
  2020-01-09T15:58:47Z checking_for_snapshot 
  2020-01-09T15:58:47Z finish_checking_for_snapshot after 220ms
  2020-01-09T15:58:47Z get_buildlet 
  2020-01-09T16:05:26Z finish_get_buildlet after 6m39.3s
  2020-01-09T16:05:26Z using_buildlet 10.240.0.155:80
  2020-01-09T16:05:26Z write_go_bootstrap_tar 
  2020-01-09T16:05:26Z write_version_tar 
  2020-01-09T16:05:26Z get_source go@83d7ec855bf73948effea263cb4ee3b2d2474c92
  2020-01-09T16:05:27Z finish_get_source after 0s; go@83d7ec855bf73948effea263cb4ee3b2d2474c92
  2020-01-09T16:05:27Z write_go_src_tar 
  2020-01-09T16:05:29Z finish_write_go_src_tar after 2.18s
  2020-01-09T16:05:29Z finish_write_go_bootstrap_tar after 2.6s
  2020-01-09T16:05:29Z make_and_test 
  2020-01-09T16:05:29Z make src/make.bash
  2020-01-09T16:08:07Z finish_make after 2m37.3s; src/make.bash
  2020-01-09T16:08:07Z clean_for_snapshot 
  2020-01-09T16:08:07Z finish_clean_for_snapshot after 89.7ms
  2020-01-09T16:08:07Z write_snapshot_to_gcs 
  2020-01-09T16:08:07Z fetch_snapshot_reader_from_buildlet 
  2020-01-09T16:08:07Z finish_fetch_snapshot_reader_from_buildlet after 64.7ms
  2020-01-09T16:08:17Z finish_write_snapshot_to_gcs after 9.85s
  2020-01-09T16:08:17Z discovering_tests 
  2020-01-09T16:08:17Z get_test_stats 
  2020-01-09T16:08:17Z finish_get_test_stats after 0s
  2020-01-09T16:08:17Z starting_tests 252 tests
  2020-01-09T16:08:17Z run_tests_multi 10.240.0.155:80: [go_test:archive/tar go_test:archive/zip go_test:bufio]
  2020-01-09T16:08:22Z finish_run_tests_multi after 4.96s; 10.240.0.155:80: [go_test:archive/tar go_test:archive/zip go_test:bufio]
  2020-01-09T16:08:22Z run_tests_multi 10.240.0.155:80: [go_test:bytes go_test:compress/bzip2 go_test:compress/flate]
  2020-01-09T16:08:27Z finish_run_tests_multi after 4.87s; 10.240.0.155:80: [go_test:bytes go_test:compress/bzip2 go_test:compress/flate]
  2020-01-09T16:08:27Z run_tests_multi 10.240.0.155:80: [go_test:compress/gzip go_test:compress/lzw go_test:compress/zlib]
  2020-01-09T16:08:30Z finish_run_tests_multi after 2.27s; 10.240.0.155:80: [go_test:compress/gzip go_test:compress/lzw go_test:compress/zlib]
  2020-01-09T16:08:30Z run_tests_multi 10.240.0.155:80: [go_test:container/heap go_test:container/list go_test:container/ring]
  2020-01-09T16:08:31Z finish_run_tests_multi after 1.41s; 10.240.0.155:80: [go_test:container/heap go_test:container/list go_test:container/ring]
  2020-01-09T16:08:31Z run_tests_multi 10.240.0.155:80: [go_test:context go_test:crypto go_test:crypto/aes]
  2020-01-09T16:08:35Z finish_run_tests_multi after 4.29s; 10.240.0.155:80: [go_test:context go_test:crypto go_test:crypto/aes]
  2020-01-09T16:08:35Z run_tests_multi 10.240.0.155:80: [go_test:crypto/cipher go_test:crypto/des go_test:crypto/dsa]
  2020-01-09T16:08:38Z finish_run_tests_multi after 2.09s; 10.240.0.155:80: [go_test:crypto/cipher go_test:crypto/des go_test:crypto/dsa]
  2020-01-09T16:08:38Z run_tests_multi 10.240.0.155:80: [go_test:crypto/ecdsa go_test:crypto/elliptic go_test:crypto/hmac]
  2020-01-09T16:08:40Z finish_run_tests_multi after 2.27s; 10.240.0.155:80: [go_test:crypto/ecdsa go_test:crypto/elliptic go_test:crypto/hmac]
  2020-01-09T16:08:40Z run_tests_multi 10.240.0.155:80: [go_test:crypto/internal/subtle go_test:crypto/md5 go_test:crypto/rand]
  2020-01-09T16:08:41Z finish_run_tests_multi after 1.49s; 10.240.0.155:80: [go_test:crypto/internal/subtle go_test:crypto/md5 go_test:crypto/rand]
  2020-01-09T16:08:41Z run_tests_multi 10.240.0.155:80: [go_test:crypto/rc4 go_test:crypto/rsa go_test:crypto/sha1]
  2020-01-09T16:08:43Z finish_run_tests_multi after 1.57s; 10.240.0.155:80: [go_test:crypto/rc4 go_test:crypto/rsa go_test:crypto/sha1]
  2020-01-09T16:08:43Z run_tests_multi 10.240.0.155:80: [go_test:crypto/sha256 go_test:crypto/sha512 go_test:crypto/subtle]
  2020-01-09T16:08:45Z finish_run_tests_multi after 1.48s; 10.240.0.155:80: [go_test:crypto/sha256 go_test:crypto/sha512 go_test:crypto/subtle]
  2020-01-09T16:08:45Z run_tests_multi 10.240.0.155:80: [go_test:crypto/tls go_test:crypto/x509 go_test:database/sql]
  2020-01-09T16:08:54Z finish_run_tests_multi after 8.93s; 10.240.0.155:80: [go_test:crypto/tls go_test:crypto/x509 go_test:database/sql]
  2020-01-09T16:08:54Z run_tests_multi 10.240.0.155:80: [go_test:database/sql/driver go_test:debug/dwarf go_test:debug/elf]
  2020-01-09T16:08:56Z finish_run_tests_multi after 2.64s; 10.240.0.155:80: [go_test:database/sql/driver go_test:debug/dwarf go_test:debug/elf]
  2020-01-09T16:08:56Z run_tests_multi 10.240.0.155:80: [go_test:debug/gosym go_test:debug/macho go_test:debug/pe]
  2020-01-09T16:09:00Z finish_run_tests_multi after 3.81s; 10.240.0.155:80: [go_test:debug/gosym go_test:debug/macho go_test:debug/pe]
  2020-01-09T16:09:00Z run_tests_multi 10.240.0.155:80: [go_test:debug/plan9obj go_test:encoding/ascii85 go_test:encoding/asn1]
  2020-01-09T16:09:02Z finish_run_tests_multi after 1.61s; 10.240.0.155:80: [go_test:debug/plan9obj go_test:encoding/ascii85 go_test:encoding/asn1]
  2020-01-09T16:09:02Z run_tests_multi 10.240.0.155:80: [go_test:encoding/base32 go_test:encoding/base64 go_test:encoding/binary]
  2020-01-09T16:09:04Z finish_run_tests_multi after 1.91s; 10.240.0.155:80: [go_test:encoding/base32 go_test:encoding/base64 go_test:encoding/binary]
  2020-01-09T16:09:04Z run_tests_multi 10.240.0.155:80: [go_test:encoding/csv go_test:encoding/gob go_test:encoding/hex]
  2020-01-09T16:09:06Z finish_run_tests_multi after 2.45s; 10.240.0.155:80: [go_test:encoding/csv go_test:encoding/gob go_test:encoding/hex]
  2020-01-09T16:09:06Z run_tests_multi 10.240.0.155:80: [go_test:encoding/json go_test:encoding/pem go_test:encoding/xml]
  2020-01-09T16:09:10Z finish_run_tests_multi after 3.56s; 10.240.0.155:80: [go_test:encoding/json go_test:encoding/pem go_test:encoding/xml]
  2020-01-09T16:09:10Z run_tests_multi 10.240.0.155:80: [go_test:errors go_test:expvar go_test:flag]
  2020-01-09T16:09:12Z finish_run_tests_multi after 2.08s; 10.240.0.155:80: [go_test:errors go_test:expvar go_test:flag]
  2020-01-09T16:09:12Z run_tests_multi 10.240.0.155:80: [go_test:fmt go_test:go/ast go_test:go/build]
  2020-01-09T16:09:17Z finish_run_tests_multi after 4.29s; 10.240.0.155:80: [go_test:fmt go_test:go/ast go_test:go/build]
  2020-01-09T16:09:17Z run_tests_multi 10.240.0.155:80: [go_test:go/constant go_test:go/doc go_test:go/format]
  2020-01-09T16:09:19Z finish_run_tests_multi after 1.91s; 10.240.0.155:80: [go_test:go/constant go_test:go/doc go_test:go/format]
  2020-01-09T16:09:19Z run_tests_multi 10.240.0.155:80: [go_test:go/importer go_test:go/internal/gccgoimporter go_test:go/internal/gcimporter]
  2020-01-09T16:09:22Z finish_run_tests_multi after 3.7s; 10.240.0.155:80: [go_test:go/importer go_test:go/internal/gccgoimporter go_test:go/internal/gcimporter]
  2020-01-09T16:09:22Z run_tests_multi 10.240.0.155:80: [go_test:go/internal/srcimporter go_test:go/parser go_test:go/printer]
  2020-01-09T16:09:28Z finish_run_tests_multi after 6.03s; 10.240.0.155:80: [go_test:go/internal/srcimporter go_test:go/parser go_test:go/printer]
  2020-01-09T16:09:28Z run_tests_multi 10.240.0.155:80: [go_test:go/scanner go_test:go/token go_test:go/types]
  2020-01-09T16:09:34Z finish_run_tests_multi after 5.43s; 10.240.0.155:80: [go_test:go/scanner go_test:go/token go_test:go/types]
  2020-01-09T16:09:34Z run_tests_multi 10.240.0.155:80: [go_test:hash go_test:hash/adler32 go_test:hash/crc32]
  2020-01-09T16:09:36Z finish_run_tests_multi after 1.66s; 10.240.0.155:80: [go_test:hash go_test:hash/adler32 go_test:hash/crc32]
  2020-01-09T16:09:36Z run_tests_multi 10.240.0.155:80: [go_test:hash/crc64 go_test:hash/fnv go_test:html]
  2020-01-09T16:09:37Z finish_run_tests_multi after 1.39s; 10.240.0.155:80: [go_test:hash/crc64 go_test:hash/fnv go_test:html]
  2020-01-09T16:09:37Z run_tests_multi 10.240.0.155:80: [go_test:html/template go_test:image go_test:image/color]
  2020-01-09T16:09:40Z finish_run_tests_multi after 2.81s; 10.240.0.155:80: [go_test:html/template go_test:image go_test:image/color]
  2020-01-09T16:09:40Z run_tests_multi 10.240.0.155:80: [go_test:image/draw go_test:image/gif go_test:image/jpeg]
  2020-01-09T16:09:42Z finish_run_tests_multi after 2.32s; 10.240.0.155:80: [go_test:image/draw go_test:image/gif go_test:image/jpeg]
  2020-01-09T16:09:42Z run_tests_multi 10.240.0.155:80: [go_test:image/png go_test:index/suffixarray go_test:internal/cpu]
  2020-01-09T16:09:51Z finish_run_tests_multi after 8.47s; 10.240.0.155:80: [go_test:image/png go_test:index/suffixarray go_test:internal/cpu]
  2020-01-09T16:09:51Z run_tests_multi 10.240.0.155:80: [go_test:internal/fmtsort go_test:internal/poll go_test:internal/singleflight]
  2020-01-09T16:09:54Z finish_run_tests_multi after 3.34s; 10.240.0.155:80: [go_test:internal/fmtsort go_test:internal/poll go_test:internal/singleflight]
  2020-01-09T16:09:54Z run_tests_multi 10.240.0.155:80: [go_test:internal/trace go_test:internal/x/crypto/chacha20poly1305 go_test:internal/x/crypto/cryptobyte]
  2020-01-09T16:09:57Z finish_run_tests_multi after 2.79s; 10.240.0.155:80: [go_test:internal/trace go_test:internal/x/crypto/chacha20poly1305 go_test:internal/x/crypto/cryptobyte]
  2020-01-09T16:09:57Z run_tests_multi 10.240.0.155:80: [go_test:internal/x/crypto/curve25519 go_test:internal/x/crypto/hkdf go_test:internal/x/crypto/internal/chacha20]
  2020-01-09T16:09:59Z finish_run_tests_multi after 1.39s; 10.240.0.155:80: [go_test:internal/x/crypto/curve25519 go_test:internal/x/crypto/hkdf go_test:internal/x/crypto/internal/chacha20]
  2020-01-09T16:09:59Z run_tests_multi 10.240.0.155:80: [go_test:internal/x/crypto/poly1305 go_test:internal/x/net/dns/dnsmessage go_test:internal/x/net/http/httpguts]
  2020-01-09T16:10:02Z finish_run_tests_multi after 3.11s; 10.240.0.155:80: [go_test:internal/x/crypto/poly1305 go_test:internal/x/net/dns/dnsmessage go_test:internal/x/net/http/httpguts]
  2020-01-09T16:10:02Z run_tests_multi 10.240.0.155:80: [go_test:internal/x/net/http/httpproxy go_test:internal/x/net/http2/hpack go_test:internal/x/net/idna]
  2020-01-09T16:10:04Z finish_run_tests_multi after 1.97s; 10.240.0.155:80: [go_test:internal/x/net/http/httpproxy go_test:internal/x/net/http2/hpack go_test:internal/x/net/idna]
  2020-01-09T16:10:04Z run_tests_multi 10.240.0.155:80: [go_test:internal/x/net/nettest go_test:internal/x/net/route go_test:internal/x/text/transform]
  2020-01-09T16:10:06Z finish_run_tests_multi after 2.32s; 10.240.0.155:80: [go_test:internal/x/net/nettest go_test:internal/x/net/route go_test:internal/x/text/transform]
  2020-01-09T16:10:06Z run_tests_multi 10.240.0.155:80: [go_test:internal/x/text/unicode/norm go_test:internal/xcoff go_test:io]
  2020-01-09T16:10:08Z finish_run_tests_multi after 1.78s; 10.240.0.155:80: [go_test:internal/x/text/unicode/norm go_test:internal/xcoff go_test:io]
  2020-01-09T16:10:08Z run_tests_multi 10.240.0.155:80: [go_test:io/ioutil go_test:log go_test:log/syslog]
  2020-01-09T16:10:11Z finish_run_tests_multi after 2.88s; 10.240.0.155:80: [go_test:io/ioutil go_test:log go_test:log/syslog]
  2020-01-09T16:10:11Z run_tests_multi 10.240.0.155:80: [go_test:math go_test:math/big go_test:math/bits]
  2020-01-09T16:10:19Z finish_run_tests_multi after 7.82s; 10.240.0.155:80: [go_test:math go_test:math/big go_test:math/bits]
  2020-01-09T16:10:19Z run_tests_multi 10.240.0.155:80: [go_test:math/cmplx go_test:math/rand go_test:mime]
  2020-01-09T16:10:21Z finish_run_tests_multi after 2.07s; 10.240.0.155:80: [go_test:math/cmplx go_test:math/rand go_test:mime]
  2020-01-09T16:10:21Z run_tests_multi 10.240.0.155:80: [go_test:mime/multipart go_test:mime/quotedprintable go_test:net]
  2020-01-09T16:10:37Z finish_run_tests_multi after 16.1s; 10.240.0.155:80: [go_test:mime/multipart go_test:mime/quotedprintable go_test:net]
  2020-01-09T16:10:37Z run_tests_multi 10.240.0.155:80: [go_test:net/http go_test:net/http/cgi go_test:net/http/cookiejar]
  2020-01-09T16:10:50Z finish_run_tests_multi after 12.9s; 10.240.0.155:80: [go_test:net/http go_test:net/http/cgi go_test:net/http/cookiejar]
  2020-01-09T16:10:50Z run_tests_multi 10.240.0.155:80: [go_test:net/http/fcgi go_test:net/http/httptest go_test:net/http/httptrace]
  2020-01-09T16:10:54Z finish_run_tests_multi after 3.99s; 10.240.0.155:80: [go_test:net/http/fcgi go_test:net/http/httptest go_test:net/http/httptrace]
  2020-01-09T16:10:54Z run_tests_multi 10.240.0.155:80: [go_test:net/http/httputil go_test:net/http/internal go_test:net/http/pprof]
  2020-01-09T16:10:59Z finish_run_tests_multi after 4.32s; 10.240.0.155:80: [go_test:net/http/httputil go_test:net/http/internal go_test:net/http/pprof]
  2020-01-09T16:10:59Z run_tests_multi 10.240.0.155:80: [go_test:net/internal/socktest go_test:net/mail go_test:net/rpc]
  2020-01-09T16:11:01Z finish_run_tests_multi after 2.18s; 10.240.0.155:80: [go_test:net/internal/socktest go_test:net/mail go_test:net/rpc]
  2020-01-09T16:11:01Z run_tests_multi 10.240.0.155:80: [go_test:net/rpc/jsonrpc go_test:net/smtp go_test:net/textproto]
  2020-01-09T16:11:03Z finish_run_tests_multi after 2.15s; 10.240.0.155:80: [go_test:net/rpc/jsonrpc go_test:net/smtp go_test:net/textproto]
  2020-01-09T16:11:03Z run_tests_multi 10.240.0.155:80: [go_test:net/url go_test:os go_test:os/exec]
  2020-01-09T16:11:08Z finish_run_tests_multi after 5.03s; 10.240.0.155:80: [go_test:net/url go_test:os go_test:os/exec]
  2020-01-09T16:11:08Z run_tests_multi 10.240.0.155:80: [go_test:os/signal go_test:os/user go_test:path]
  2020-01-09T16:11:15Z finish_run_tests_multi after 6.25s; 10.240.0.155:80: [go_test:os/signal go_test:os/user go_test:path]
  2020-01-09T16:11:15Z run_tests_multi 10.240.0.155:80: [go_test:path/filepath go_test:plugin go_test:reflect]
  2020-01-09T16:11:21Z finish_run_tests_multi after 5.63s; 10.240.0.155:80: [go_test:path/filepath go_test:plugin go_test:reflect]
  2020-01-09T16:11:21Z run_tests_multi 10.240.0.155:80: [go_test:regexp go_test:regexp/syntax go_test:runtime]
  2020-01-09T16:11:51Z still_waiting_on_test go_test:regexp
  2020-01-09T16:12:01Z finish_run_tests_multi after 40.7s; 10.240.0.155:80: [go_test:regexp go_test:regexp/syntax go_test:runtime]
  2020-01-09T16:12:01Z run_tests_multi 10.240.0.155:80: [go_test:runtime/debug go_test:runtime/internal/atomic go_test:runtime/internal/math]
  2020-01-09T16:12:03Z finish_run_tests_multi after 1.44s; 10.240.0.155:80: [go_test:runtime/debug go_test:runtime/internal/atomic go_test:runtime/internal/math]
  2020-01-09T16:12:03Z run_tests_multi 10.240.0.155:80: [go_test:runtime/internal/sys go_test:runtime/pprof go_test:runtime/pprof/internal/profile]
  2020-01-09T16:12:12Z finish_run_tests_multi after 8.73s; 10.240.0.155:80: [go_test:runtime/internal/sys go_test:runtime/pprof go_test:runtime/pprof/internal/profile]
  2020-01-09T16:12:12Z run_tests_multi 10.240.0.155:80: [go_test:runtime/trace go_test:sort go_test:strconv]
  2020-01-09T16:12:19Z finish_run_tests_multi after 6.81s; 10.240.0.155:80: [go_test:runtime/trace go_test:sort go_test:strconv]
  2020-01-09T16:12:19Z run_tests_multi 10.240.0.155:80: [go_test:strings go_test:sync go_test:sync/atomic]
  2020-01-09T16:12:26Z finish_run_tests_multi after 7.62s; 10.240.0.155:80: [go_test:strings go_test:sync go_test:sync/atomic]
  2020-01-09T16:12:26Z run_tests_multi 10.240.0.155:80: [go_test:syscall go_test:testing go_test:testing/quick]
  2020-01-09T16:12:31Z finish_run_tests_multi after 4.79s; 10.240.0.155:80: [go_test:syscall go_test:testing go_test:testing/quick]
  2020-01-09T16:12:31Z run_tests_multi 10.240.0.155:80: [go_test:text/scanner go_test:text/tabwriter go_test:text/template]
  2020-01-09T16:12:33Z finish_run_tests_multi after 2.3s; 10.240.0.155:80: [go_test:text/scanner go_test:text/tabwriter go_test:text/template]
  2020-01-09T16:12:33Z run_tests_multi 10.240.0.155:80: [go_test:text/template/parse go_test:time go_test:unicode]
  2020-01-09T16:12:41Z finish_run_tests_multi after 7.1s; 10.240.0.155:80: [go_test:text/template/parse go_test:time go_test:unicode]
  2020-01-09T16:12:41Z run_tests_multi 10.240.0.155:80: [go_test:unicode/utf16 go_test:unicode/utf8 go_test:cmd/addr2line]
  2020-01-09T16:12:44Z finish_run_tests_multi after 2.99s; 10.240.0.155:80: [go_test:unicode/utf16 go_test:unicode/utf8 go_test:cmd/addr2line]
  2020-01-09T16:12:44Z run_tests_multi 10.240.0.155:80: [go_test:cmd/api go_test:cmd/asm/internal/asm go_test:cmd/asm/internal/lex]
  2020-01-09T16:12:47Z finish_run_tests_multi after 2.93s; 10.240.0.155:80: [go_test:cmd/api go_test:cmd/asm/internal/asm go_test:cmd/asm/internal/lex]
  2020-01-09T16:12:47Z run_tests_multi 10.240.0.155:80: [go_test:cmd/compile go_test:cmd/compile/internal/gc go_test:cmd/compile/internal/ssa]
  2020-01-09T16:13:17Z still_waiting_on_test go_test:cmd/compile
  2020-01-09T16:13:23Z finish_run_tests_multi after 36.5s; 10.240.0.155:80: [go_test:cmd/compile go_test:cmd/compile/internal/gc go_test:cmd/compile/internal/ssa]
  2020-01-09T16:13:23Z run_tests_multi 10.240.0.155:80: [go_test:cmd/compile/internal/syntax go_test:cmd/compile/internal/test go_test:cmd/compile/internal/types]
  2020-01-09T16:13:25Z finish_run_tests_multi after 2.15s; 10.240.0.155:80: [go_test:cmd/compile/internal/syntax go_test:cmd/compile/internal/test go_test:cmd/compile/internal/types]
  2020-01-09T16:13:25Z run_tests_multi 10.240.0.155:80: [go_test:cmd/cover go_test:cmd/doc go_test:cmd/fix]
  2020-01-09T16:13:31Z finish_run_tests_multi after 4.9s; 10.240.0.155:80: [go_test:cmd/cover go_test:cmd/doc go_test:cmd/fix]
  2020-01-09T16:13:31Z run_tests_multi 10.240.0.155:80: [go_test:cmd/go go_test:cmd/go/internal/cache go_test:cmd/go/internal/dirhash]
  2020-01-09T16:14:01Z still_waiting_on_test go_test:cmd/go
  2020-01-09T16:14:31Z still_waiting_on_test go_test:cmd/go
  2020-01-09T16:14:44Z finish_run_tests_multi after 1m13.9s; 10.240.0.155:80: [go_test:cmd/go go_test:cmd/go/internal/cache go_test:cmd/go/internal/dirhash]
  2020-01-09T16:14:44Z run_tests_multi 10.240.0.155:80: [go_test:cmd/go/internal/generate go_test:cmd/go/internal/get go_test:cmd/go/internal/imports]
  2020-01-09T16:14:47Z finish_run_tests_multi after 2.43s; 10.240.0.155:80: [go_test:cmd/go/internal/generate go_test:cmd/go/internal/get go_test:cmd/go/internal/imports]
  2020-01-09T16:14:47Z run_tests_multi 10.240.0.155:80: [go_test:cmd/go/internal/load go_test:cmd/go/internal/lockedfile go_test:cmd/go/internal/lockedfile/internal/filelock]
  2020-01-09T16:14:49Z finish_run_tests_multi after 1.72s; 10.240.0.155:80: [go_test:cmd/go/internal/load go_test:cmd/go/internal/lockedfile go_test:cmd/go/internal/lockedfile/internal/filelock]
  2020-01-09T16:14:49Z run_tests_multi 10.240.0.155:80: [go_test:cmd/go/internal/modconv go_test:cmd/go/internal/modfetch go_test:cmd/go/internal/modfetch/codehost]
  2020-01-09T16:14:52Z finish_run_tests_multi after 2.73s; 10.240.0.155:80: [go_test:cmd/go/internal/modconv go_test:cmd/go/internal/modfetch go_test:cmd/go/internal/modfetch/codehost]
  2020-01-09T16:14:52Z run_tests_multi 10.240.0.155:80: [go_test:cmd/go/internal/modfile go_test:cmd/go/internal/modload go_test:cmd/go/internal/module]
  2020-01-09T16:14:54Z finish_run_tests_multi after 2.37s; 10.240.0.155:80: [go_test:cmd/go/internal/modfile go_test:cmd/go/internal/modload go_test:cmd/go/internal/module]
  2020-01-09T16:14:54Z run_tests_multi 10.240.0.155:80: [go_test:cmd/go/internal/mvs go_test:cmd/go/internal/par go_test:cmd/go/internal/search]
  2020-01-09T16:14:56Z finish_run_tests_multi after 1.48s; 10.240.0.155:80: [go_test:cmd/go/internal/mvs go_test:cmd/go/internal/par go_test:cmd/go/internal/search]
  2020-01-09T16:14:56Z run_tests_multi 10.240.0.155:80: [go_test:cmd/go/internal/semver go_test:cmd/go/internal/txtar go_test:cmd/go/internal/web2]
  2020-01-09T16:14:58Z finish_run_tests_multi after 1.82s; 10.240.0.155:80: [go_test:cmd/go/internal/semver go_test:cmd/go/internal/txtar go_test:cmd/go/internal/web2]
  2020-01-09T16:14:58Z run_tests_multi 10.240.0.155:80: [go_test:cmd/go/internal/work go_test:cmd/gofmt go_test:cmd/internal/buildid]
  2020-01-09T16:15:00Z finish_run_tests_multi after 2.46s; 10.240.0.155:80: [go_test:cmd/go/internal/work go_test:cmd/gofmt go_test:cmd/internal/buildid]
  2020-01-09T16:15:00Z run_tests_multi 10.240.0.155:80: [go_test:cmd/internal/dwarf go_test:cmd/internal/edit go_test:cmd/internal/goobj]
  2020-01-09T16:15:02Z finish_run_tests_multi after 1.79s; 10.240.0.155:80: [go_test:cmd/internal/dwarf go_test:cmd/internal/edit go_test:cmd/internal/goobj]
  2020-01-09T16:15:02Z run_tests_multi 10.240.0.155:80: [go_test:cmd/internal/obj go_test:cmd/internal/obj/arm64 go_test:cmd/internal/obj/x86]
  2020-01-09T16:15:05Z finish_run_tests_multi after 2.91s; 10.240.0.155:80: [go_test:cmd/internal/obj go_test:cmd/internal/obj/arm64 go_test:cmd/internal/obj/x86]
  2020-01-09T16:15:05Z run_tests_multi 10.240.0.155:80: [go_test:cmd/internal/objabi go_test:cmd/internal/src go_test:cmd/internal/test2json]
  2020-01-09T16:15:07Z finish_run_tests_multi after 1.59s; 10.240.0.155:80: [go_test:cmd/internal/objabi go_test:cmd/internal/src go_test:cmd/internal/test2json]
  2020-01-09T16:15:07Z run_tests_multi 10.240.0.155:80: [go_test:cmd/link go_test:cmd/link/internal/ld go_test:cmd/link/internal/sym]
  2020-01-09T16:15:15Z finish_run_tests_multi after 8.59s; 10.240.0.155:80: [go_test:cmd/link go_test:cmd/link/internal/ld go_test:cmd/link/internal/sym]
  2020-01-09T16:15:15Z run_tests_multi 10.240.0.155:80: [go_test:cmd/nm go_test:cmd/objdump go_test:cmd/pack]
  2020-01-09T16:15:20Z finish_run_tests_multi after 4.34s; 10.240.0.155:80: [go_test:cmd/nm go_test:cmd/objdump go_test:cmd/pack]
  2020-01-09T16:15:20Z run_tests_multi 10.240.0.155:80: [go_test:cmd/trace go_test:cmd/vet]
  2020-01-09T16:15:31Z finish_run_tests_multi after 10.6s; 10.240.0.155:80: [go_test:cmd/trace go_test:cmd/vet]
  2020-01-09T16:15:31Z run_test:osusergo 10.240.0.155:80
  2020-01-09T16:15:32Z finish_run_test:osusergo after 1.07s; 10.240.0.155:80
  2020-01-09T16:15:32Z run_test:runtime:cpu124 10.240.0.155:80
  2020-01-09T16:16:02Z still_waiting_on_test runtime:cpu124
  2020-01-09T16:16:32Z still_waiting_on_test runtime:cpu124
  2020-01-09T16:16:41Z finish_run_test:runtime:cpu124 after 1m9.7s; 10.240.0.155:80
  2020-01-09T16:16:41Z run_test:moved_goroot 10.240.0.155:80
  2020-01-09T16:16:46Z finish_run_test:moved_goroot after 3.98s; 10.240.0.155:80
  2020-01-09T16:16:46Z run_test:nolibgcc:crypto/x509 10.240.0.155:80
  2020-01-09T16:16:47Z finish_run_test:nolibgcc:crypto/x509 after 1.85s; 10.240.0.155:80
  2020-01-09T16:16:47Z run_test:nolibgcc:net 10.240.0.155:80
  2020-01-09T16:16:49Z finish_run_test:nolibgcc:net after 1.31s; 10.240.0.155:80
  2020-01-09T16:16:49Z run_test:nolibgcc:os/user 10.240.0.155:80
  2020-01-09T16:16:50Z finish_run_test:nolibgcc:os/user after 1s; 10.240.0.155:80
  2020-01-09T16:16:50Z run_test:sync_cpu 10.240.0.155:80
  2020-01-09T16:16:51Z finish_run_test:sync_cpu after 1.34s; 10.240.0.155:80
  2020-01-09T16:16:51Z run_test:race 10.240.0.155:80
  2020-01-09T16:17:21Z still_waiting_on_test race
  2020-01-09T16:17:42Z finish_run_test:race after 50.3s; 10.240.0.155:80
  2020-01-09T16:17:42Z run_test:cgo_stdio 10.240.0.155:80
  2020-01-09T16:17:44Z finish_run_test:cgo_stdio after 1.99s; 10.240.0.155:80
  2020-01-09T16:17:44Z run_test:cgo_life 10.240.0.155:80
  2020-01-09T16:17:45Z finish_run_test:cgo_life after 1.43s; 10.240.0.155:80
  2020-01-09T16:17:45Z run_test:cgo_test 10.240.0.155:80
  2020-01-09T16:18:15Z still_waiting_on_test cgo_test
  2020-01-09T16:18:17Z finish_run_test:cgo_test after 31.1s; 10.240.0.155:80
  2020-01-09T16:18:17Z run_test:testgodefs 10.240.0.155:80
  2020-01-09T16:18:18Z finish_run_test:testgodefs after 966.6ms; 10.240.0.155:80
  2020-01-09T16:18:18Z run_test:testso 10.240.0.155:80
  2020-01-09T16:18:19Z finish_run_test:testso after 1.18s; 10.240.0.155:80
  2020-01-09T16:18:19Z run_test:testsovar 10.240.0.155:80
  2020-01-09T16:18:20Z finish_run_test:testsovar after 1.26s; 10.240.0.155:80
  2020-01-09T16:18:20Z run_test:testcarchive 10.240.0.155:80
  2020-01-09T16:18:50Z still_waiting_on_test testcarchive
  2020-01-09T16:18:55Z finish_run_test:testcarchive after 34.6s; 10.240.0.155:80
  2020-01-09T16:18:55Z run_test:testcshared 10.240.0.155:80
  2020-01-09T16:19:00Z finish_run_test:testcshared after 5.25s; 10.240.0.155:80
  2020-01-09T16:19:00Z run_test:cgo_errors 10.240.0.155:80
  2020-01-09T16:19:11Z finish_run_test:cgo_errors after 11.2s; 10.240.0.155:80
  2020-01-09T16:19:11Z run_test:doc_progs 10.240.0.155:80
  2020-01-09T16:19:19Z finish_run_test:doc_progs after 7.56s; 10.240.0.155:80
  2020-01-09T16:19:19Z run_test:wiki 10.240.0.155:80
  2020-01-09T16:19:23Z finish_run_test:wiki after 3.45s; 10.240.0.155:80
  2020-01-09T16:19:23Z run_test:codewalk 10.240.0.155:80
  2020-01-09T16:19:25Z finish_run_test:codewalk after 2.33s; 10.240.0.155:80
  2020-01-09T16:19:25Z run_test:bench_go1 10.240.0.155:80
  2020-01-09T16:19:28Z finish_run_test:bench_go1 after 3.23s; 10.240.0.155:80
  2020-01-09T16:19:28Z run_test:test:0_10 10.240.0.155:80
  2020-01-09T16:19:57Z finish_run_test:test:0_10 after 28.7s; 10.240.0.155:80
  2020-01-09T16:19:57Z run_test:test:1_10 10.240.0.155:80
  2020-01-09T16:20:13Z finish_run_test:test:1_10 after 15.4s; 10.240.0.155:80
  2020-01-09T16:20:13Z run_test:test:2_10 10.240.0.155:80
  2020-01-09T16:20:27Z finish_run_test:test:2_10 after 14.8s; 10.240.0.155:80
  2020-01-09T16:20:27Z run_test:test:3_10 10.240.0.155:80
  2020-01-09T16:20:45Z finish_run_test:test:3_10 after 17.5s; 10.240.0.155:80
  2020-01-09T16:20:45Z run_test:test:4_10 10.240.0.155:80
  2020-01-09T16:21:00Z finish_run_test:test:4_10 after 15s; 10.240.0.155:80
  2020-01-09T16:21:00Z run_test:test:5_10 10.240.0.155:80
  2020-01-09T16:21:12Z finish_run_test:test:5_10 after 11.3s; 10.240.0.155:80
  2020-01-09T16:21:12Z run_test:test:6_10 10.240.0.155:80
  2020-01-09T16:21:21Z finish_run_test:test:6_10 after 9.63s; 10.240.0.155:80
  2020-01-09T16:21:21Z run_test:test:7_10 10.240.0.155:80
  +11.6s (now)

Build log:
freebsd-amd64-10_3 at 83d7ec855bf73948effea263cb4ee3b2d2474c92

:: Running /tmp/workdir/go/src/make.bash with args ["/tmp/workdir/go/src/make.bash"] and env ["PATH=/bin:/sbin:/usr/bin:/usr/local/bin:/usr/local/bin" "PWD=/" "HOME=/" "RC_PID=17" "WORKDIR=/tmp/workdir" "GOROOT_BOOTSTRAP=/tmp/workdir/go1.4" "GO_BUILDER_NAME=freebsd-amd64-10_3" "CC=clang" "GOBIN=" "TMPDIR=/tmp/workdir/tmp" "GOCACHE=/tmp/workdir/gocache"] in dir /tmp/workdir/go/src

Building Go cmd/dist using /tmp/workdir/go1.4.
Building Go toolchain1 using /tmp/workdir/go1.4.
Building Go bootstrap cmd/go (go_bootstrap) using Go toolchain1.
Building Go toolchain2 using go_bootstrap and Go toolchain1.
Building Go toolchain3 using go_bootstrap and Go toolchain2.
Building packages and commands for freebsd/amd64.
---
Installed Go for freebsd/amd64 in /tmp/workdir/go
Installed commands in /tmp/workdir/go/bin

##### Testing packages.
ok  	archive/tar	0.037s
ok  	archive/zip	0.731s
ok  	bufio	0.089s
ok  	bytes	0.878s
ok  	compress/bzip2	0.122s
ok  	compress/flate	0.827s
ok  	compress/gzip	0.140s
ok  	compress/lzw	0.080s
ok  	compress/zlib	0.518s
ok  	container/heap	0.013s
ok  	container/list	0.003s
ok  	container/ring	0.016s
ok  	context	1.007s
ok  	crypto	0.004s
ok  	crypto/aes	0.023s
ok  	crypto/cipher	0.186s
ok  	crypto/des	0.015s
ok  	crypto/dsa	0.007s
ok  	crypto/ecdsa	0.114s
ok  	crypto/elliptic	0.531s
ok  	crypto/hmac	0.008s
ok  	crypto/internal/subtle	0.003s
ok  	crypto/md5	0.005s
ok  	crypto/rand	0.033s
ok  	crypto/rc4	0.050s
ok  	crypto/rsa	0.083s
ok  	crypto/sha1	0.004s
ok  	crypto/sha256	0.005s
ok  	crypto/sha512	0.004s
ok  	crypto/subtle	0.004s
ok  	crypto/tls	0.796s
ok  	crypto/x509	1.967s
ok  	database/sql	0.764s
ok  	database/sql/driver	0.003s
ok  	debug/dwarf	0.009s
ok  	debug/elf	0.031s
ok  	debug/gosym	2.065s
ok  	debug/macho	0.007s
ok  	debug/pe	0.009s
ok  	debug/plan9obj	0.003s
ok  	encoding/ascii85	0.006s
ok  	encoding/asn1	0.006s
ok  	encoding/base32	0.025s
ok  	encoding/base64	0.009s
ok  	encoding/binary	0.006s
ok  	encoding/csv	0.058s
ok  	encoding/gob	0.030s
ok  	encoding/hex	0.049s
ok  	encoding/json	0.362s
ok  	encoding/pem	0.013s
ok  	encoding/xml	0.027s
ok  	errors	0.045s
ok  	expvar	0.004s
ok  	flag	0.004s
ok  	fmt	0.075s
ok  	go/ast	0.010s
ok  	go/build	0.139s
ok  	go/constant	0.006s
ok  	go/doc	0.036s
ok  	go/format	0.007s
ok  	go/importer	0.184s
ok  	go/internal/gccgoimporter	0.008s
ok  	go/internal/gcimporter	1.230s
ok  	go/internal/srcimporter	2.759s
ok  	go/parser	0.023s
ok  	go/printer	0.357s
ok  	go/scanner	0.009s
ok  	go/token	0.029s
ok  	go/types	0.812s
ok  	hash	0.015s
ok  	hash/adler32	0.010s
ok  	hash/crc32	0.006s
ok  	hash/crc64	0.004s
ok  	hash/fnv	0.005s
ok  	html	0.004s
ok  	html/template	0.038s
ok  	image	0.071s
ok  	image/color	0.026s
ok  	image/draw	0.062s
ok  	image/gif	0.415s
ok  	image/jpeg	0.233s
ok  	image/png	0.114s
ok  	index/suffixarray	0.007s
ok  	internal/cpu	0.008s
ok  	internal/fmtsort	0.005s
ok  	internal/poll	0.021s
ok  	internal/singleflight	0.053s
ok  	internal/trace	1.229s
ok  	internal/x/crypto/chacha20poly1305	0.082s
ok  	internal/x/crypto/cryptobyte	0.006s
ok  	internal/x/crypto/curve25519	0.021s
ok  	internal/x/crypto/hkdf	0.004s
ok  	internal/x/crypto/internal/chacha20	0.052s
ok  	internal/x/crypto/poly1305	0.032s
ok  	internal/x/net/dns/dnsmessage	0.057s
ok  	internal/x/net/http/httpguts	0.005s
ok  	internal/x/net/http/httpproxy	0.006s
ok  	internal/x/net/http2/hpack	0.005s
ok  	internal/x/net/idna	0.038s
ok  	internal/x/net/nettest	0.712s
ok  	internal/x/net/route	0.009s
ok  	internal/x/text/transform	0.008s
ok  	internal/x/text/unicode/norm	0.004s
ok  	internal/xcoff	0.012s
ok  	io	0.040s
ok  	io/ioutil	0.005s
ok  	log	0.027s
ok  	log/syslog	1.248s
ok  	math	0.025s
ok  	math/big	1.780s
ok  	math/bits	0.008s
ok  	math/cmplx	0.005s
ok  	math/rand	0.255s
ok  	mime	0.008s
ok  	mime/multipart	0.370s
ok  	mime/quotedprintable	0.150s
ok  	net	11.158s
ok  	net/http	5.827s
ok  	net/http/cgi	0.239s
ok  	net/http/cookiejar	0.026s
ok  	net/http/fcgi	0.007s
ok  	net/http/httptest	0.072s
ok  	net/http/httptrace	0.004s
ok  	net/http/httputil	0.044s
ok  	net/http/internal	0.008s
ok  	net/http/pprof	2.107s
ok  	net/internal/socktest	0.005s
ok  	net/mail	0.007s
ok  	net/rpc	0.028s
ok  	net/rpc/jsonrpc	0.008s
ok  	net/smtp	0.012s
ok  	net/textproto	0.009s
ok  	net/url	0.013s
ok  	os	0.680s
ok  	os/exec	0.619s
ok  	os/signal	4.578s
ok  	os/user	0.005s
ok  	path	0.011s
ok  	path/filepath	0.057s
ok  	plugin	0.031s
ok  	reflect	0.131s
ok  	regexp	0.091s
ok  	regexp/syntax	0.577s
ok  	runtime	28.229s
ok  	runtime/debug	0.157s
ok  	runtime/internal/atomic	0.128s
ok  	runtime/internal/math	0.004s
ok  	runtime/internal/sys	0.048s
ok  	runtime/pprof	6.778s
ok  	runtime/pprof/internal/profile	0.003s
ok  	runtime/trace	3.081s
ok  	sort	0.081s
ok  	strconv	0.332s
ok  	strings	2.262s
ok  	sync	0.312s
ok  	sync/atomic	0.033s
ok  	syscall	0.021s
ok  	testing	1.461s
ok  	testing/quick	0.119s
ok  	text/scanner	0.029s
ok  	text/tabwriter	0.010s
ok  	text/template	0.264s
ok  	text/template/parse	0.183s
ok  	time	2.721s
ok  	unicode	0.008s
ok  	unicode/utf16	0.005s
ok  	unicode/utf8	0.007s
ok  	cmd/addr2line	1.098s
ok  	cmd/api	0.022s
ok  	cmd/asm/internal/asm	0.374s
ok  	cmd/asm/internal/lex	0.004s
ok  	cmd/compile	0.007s
ok  	cmd/compile/internal/gc	21.958s
ok  	cmd/compile/internal/ssa	0.486s
ok  	cmd/compile/internal/syntax	0.008s
ok  	cmd/compile/internal/test	0.050s [no tests to run]
ok  	cmd/compile/internal/types	0.005s
ok  	cmd/cover	2.260s
ok  	cmd/doc	0.150s
ok  	cmd/fix	2.946s
ok  	cmd/go	69.743s
ok  	cmd/go/internal/cache	1.476s
ok  	cmd/go/internal/dirhash	0.007s
ok  	cmd/go/internal/generate	0.012s
ok  	cmd/go/internal/get	0.014s
ok  	cmd/go/internal/imports	0.007s
ok  	cmd/go/internal/load	0.009s
ok  	cmd/go/internal/lockedfile	0.022s
ok  	cmd/go/internal/lockedfile/internal/filelock	0.032s
ok  	cmd/go/internal/modconv	0.019s
ok  	cmd/go/internal/modfetch	0.020s
ok  	cmd/go/internal/modfetch/codehost	0.016s
ok  	cmd/go/internal/modfile	0.008s
ok  	cmd/go/internal/modload	0.014s
ok  	cmd/go/internal/module	0.010s
ok  	cmd/go/internal/mvs	0.007s
ok  	cmd/go/internal/par	0.031s
ok  	cmd/go/internal/search	0.008s
ok  	cmd/go/internal/semver	0.004s
ok  	cmd/go/internal/txtar	0.004s
ok  	cmd/go/internal/web2	0.005s
ok  	cmd/go/internal/work	0.012s
ok  	cmd/gofmt	0.107s
ok  	cmd/internal/buildid	0.283s
ok  	cmd/internal/dwarf	0.004s
ok  	cmd/internal/edit	0.003s
ok  	cmd/internal/goobj	0.269s
ok  	cmd/internal/obj	0.008s
ok  	cmd/internal/obj/arm64	0.039s
ok  	cmd/internal/obj/x86	0.203s
ok  	cmd/internal/objabi	0.003s
ok  	cmd/internal/src	0.010s
ok  	cmd/internal/test2json	0.108s
ok  	cmd/link	5.678s
ok  	cmd/link/internal/ld	2.255s
ok  	cmd/link/internal/sym	0.007s
ok  	cmd/nm	1.877s
ok  	cmd/objdump	2.327s
ok  	cmd/pack	2.616s
ok  	cmd/trace	0.030s
ok  	cmd/vet	8.094s

##### os/user with tag osusergo
ok  	os/user	0.003s

##### GOMAXPROCS=2 runtime -cpu=1,2,4 -quick
ok  	runtime	67.254s

##### moved GOROOT
ok  	fmt	0.075s

##### Testing without libgcc.
ok  	crypto/x509	0.666s
ok  	net	0.011s
ok  	os/user	0.006s

##### sync -cpu=10
ok  	sync	0.301s

##### Testing race detector
ok  	runtime/race	35.506s
ok  	flag	1.107s
ok  	net	1.175s
ok  	os	1.076s
ok  	os/exec	3.079s
ok  	encoding/gob	1.045s
PASS
scatter = 0x60c790
hello from C
sqrt is: 0
ok  	_/tmp/workdir/go/misc/cgo/test	4.825s
ok  	flag	1.032s
ok  	os/exec	3.184s

##### ../misc/cgo/stdio

##### ../misc/cgo/life

##### ../misc/cgo/test
PASS
ok  	_/tmp/workdir/go/misc/cgo/test	1.567s
PASS
ok  	_/tmp/workdir/go/misc/cgo/test	1.927s
PASS
ok  	_/tmp/workdir/go/misc/cgo/test	1.517s
PASS
ok  	_/tmp/workdir/go/misc/cgo/testtls	0.019s
PASS
ok  	_/tmp/workdir/go/misc/cgo/testtls	0.006s
PASS
ok  	_/tmp/workdir/go/misc/cgo/testtls	0.005s
PASS
ok  	_/tmp/workdir/go/misc/cgo/nocgo	0.003s
PASS
ok  	_/tmp/workdir/go/misc/cgo/nocgo	0.005s
PASS
ok  	_/tmp/workdir/go/misc/cgo/nocgo	0.007s
PASS
ok  	_/tmp/workdir/go/misc/cgo/test	1.758s
PASS
ok  	_/tmp/workdir/go/misc/cgo/test	1.576s

##### ../misc/cgo/testgodefs

##### ../misc/cgo/testso

##### ../misc/cgo/testsovar

##### ../misc/cgo/testcarchive
PASS

##### ../misc/cgo/testcshared
PASS

##### ../misc/cgo/errors
PASS

##### ../doc/progs
        6.85 real        19.08 user         8.40 sys

##### ../doc/articles/wiki
PASS
./test.bash: line 14: 27980 Terminated              ./final-test.bin

##### ../doc/codewalk
        1.64 real         1.89 user         0.62 sys

##### ../test/bench/go1
testing: warning: no tests to run
PASS
ok  	_/tmp/workdir/go/test/bench/go1	1.644s

##### ../test

All tests passed.

[dmitshur]

This may or may not be a separate issue, but many linux trybots have been taking upwards of 20-30+ minutes up to 1.5 hours to complete recently. E.g., from https://go-review.googlesource.com/c/tools/+/214717/6#message-b0f0c1ccf6bca7c56b71540fc1f1216998891fd7:

From https://go-review.googlesource.com/c/go/+/213477/2#message-3445c3adb8d05bcb02093baa0e6c530ff11d1b42:

[dmitshur]

The freebsd-amd64-10_3 builder is long gone (removed in CL 246639), so this specific issue can be closed. (The general tracking issue for TryBot speed is #17104.)