cmd/go: tests frequently timing out on `dragonfly-amd64` since CL 412394 #53577

bcmills · 2022-06-27T19:41:54Z

go test proxy running at GOPROXY=http://127.0.0.1:55340/mod
--- FAIL: TestScript (0.02s)
…

FAIL
FAIL	cmd/go	1035.282s

None of the individual scripts was left running for longer than 30s or so, so it appears that the cmd/go tests in general have gotten much slower on this builder.

We had thought that CL 413634 and/or CL 413815 would fix the problem, but that appears not to have borne out.

greplogs -l -e $\?ms$\\Adragonfly-amd64.\*FAIL\\s+cmd/go\\s+\\d\{4}\\.\\d\*s --since=2022-04-01 --details

(39 matching logs)

(CC @golang/dragonfly)

@rsc is planning to investigate.

The text was updated successfully, but these errors were encountered:

gopherbot · 2022-06-27T19:54:45Z

Change https://go.dev/cl/414614 mentions this issue: dashboard: add known issue for dragonfly-amd64

The cmd/go tests have been timing out frequently on this builder. We are still investigating the root cause. For golang/go#53577. Change-Id: I841117e8c2cff7296869d7beedced364714b7cf9 Reviewed-on: https://go-review.googlesource.com/c/build/+/414614 Reviewed-by: David Chase <drchase@google.com> Auto-Submit: Bryan Mills <bcmills@google.com> TryBot-Result: Gopher Robot <gobot@golang.org> Run-TryBot: Bryan Mills <bcmills@google.com>

gopherbot · 2022-07-05T17:58:40Z

Change https://go.dev/cl/416134 mentions this issue: cmd/go: use package index for std in load.loadPackageData

gopherbot · 2022-07-06T21:28:09Z

Change https://go.dev/cl/416178 mentions this issue: cmd/go: make module index loading O(1)

gopherbot · 2022-07-06T21:28:10Z

Change https://go.dev/cl/416179 mentions this issue: cmd/go: avoid spurious readdir during fsys.Walk

load.loadPackageData was only using an index for modules, not for standard library packages. Other parts of the code were using the index, so there was some benefit, but not as much as you'd hope. With the index disabled, the Script/work test takes 2.2s on my Mac. With the index enabled before this CL, it took 2.0s. With the index enabled after this CL, it takes 1.6s. Before this CL, the Script/work test issued: 429 IsDir 19 IsDirWithGoFiles 7 Lstat 9072 Open 993 ReadDir 256 Stat 7 Walk 3 indexModule 24 openIndexModule 525 openIndexPackage After this CL, it issued: 19 IsDirWithGoFiles 7 Lstat 60 Open 606 ReadDir 256 Stat 7 Walk 3 indexModule 24 openIndexModule 525 openIndexPackage This speedup helps the Dragonfly builder, which has very slow file I/O and is timing out since a recent indexing change. Times for go test -run=Script/^work$ on the Dragonfly builder: 50s before indexing changes 31s full module indexing of std 46s per-package indexing of std It cuts the time for go test -run=Script/^work$ from 44s to 20s. For #53577. Change-Id: I7189a77fc7fdf61de3ab3447efc4e84d1fc52c25 Reviewed-on: https://go-review.googlesource.com/c/go/+/416134 Reviewed-by: Bryan Mills <bcmills@google.com>

For a large module, opening the index was populating tables with entries for every package in the module. If we are only using a small number of those packages, this is wasted work that can dwarf the benefit from the index. This CL changes the index reader to avoid loading all packages at module index open time. It also refactors the code somewhat for clarity. It also removes some duplication by defining that a per-package index is a per-module index containing a single package, rather than having two different formats and two different decoders. It also changes the string table to use uvarint-prefixed data instead of having to scan for a NUL byte. This makes random access to long strings more efficient - O(1) instead of O(n) - and can significantly speed up the strings.Compare operation in the binary search looking for a given package. Also add a direct test of the indexing code. For #53577. Change-Id: I7428d28133e4e7fe2d2993fa014896cd15af48af Reviewed-on: https://go-review.googlesource.com/c/go/+/416178 Reviewed-by: Bryan Mills <bcmills@google.com>

fsys.Walk is cloned from filepath.Walk, which has always handled a walk of a directory by reading the full directory before calling the callback on the directory itself. So if the callback returns fs.SkipDir, those entries are thrown away, but the expense of reading them was still incurred. (Worse, this is the expensive directory read that also calls Stat on every entry.) On machines with slow file system I/O, these reads are particularly annoying. For example, if I do go list m... there is a call to filepath.Walk that is told about $GOROOT/src/archive and responds by returning filepath.SkipDir because archive does not start with m, but it only gets the chance to do that after the archive directory has been read. (Same for all the other top-level directories.) Even something like go list github.com/foo/bar/... reads every top-level $GOPATH/src directory. When we designed filepath.WalkDir, one of the changes we made was to allow calling the callback twice for a directory: once before reading it, and then possibly again if the read produces an error (uncommon). This CL changes fsys.Walk to use that same model. None of the callbacks need changing, but now the $GOROOT/src/archive and other top-level directories won't be read when evaluating a pattern like 'm...'. For #53577. Fixes #53765. Change-Id: Idfa3b9e2cc335417bfd9d66dd584cb16f92bd12e Reviewed-on: https://go-review.googlesource.com/c/go/+/416179 Run-TryBot: Russ Cox <rsc@golang.org> Reviewed-by: Bryan Mills <bcmills@google.com> TryBot-Result: Gopher Robot <gobot@golang.org>

gopherbot · 2022-07-12T14:59:33Z

Change https://go.dev/cl/417094 mentions this issue: cmd/go: avoid indexing GOROOT packages when the compiler is 'gccgo'

The gccgo compiler does not load standard-library packages from GOROOT/src, so we cannot load those packages from the GOROOT/src index when using that compiler. This fixes TestScript/gccgo_link_c (and perhaps other gccgo tests) when a 'gccgo' executable is present. Unfortunately, only a few builders caught the broken test because 'gccgo' is not installed on most Go project builders (see #35786). For #53577. Fixes #53815. Change-Id: I11a5cf6dbf4ac9893c4d02bd6ab7ef60f67b1e87 Reviewed-on: https://go-review.googlesource.com/c/go/+/417094 TryBot-Result: Gopher Robot <gobot@golang.org> Run-TryBot: Bryan Mills <bcmills@google.com> Reviewed-by: Russ Cox <rsc@golang.org>

gopherbot · 2022-07-22T19:13:49Z

Change https://go.dev/cl/419084 mentions this issue: dashboard: use dragonfly on GCE for dragonfly-amd64 builds

load.loadPackageData was only using an index for modules, not for standard library packages. Other parts of the code were using the index, so there was some benefit, but not as much as you'd hope. With the index disabled, the Script/work test takes 2.2s on my Mac. With the index enabled before this CL, it took 2.0s. With the index enabled after this CL, it takes 1.6s. Before this CL, the Script/work test issued: 429 IsDir 19 IsDirWithGoFiles 7 Lstat 9072 Open 993 ReadDir 256 Stat 7 Walk 3 indexModule 24 openIndexModule 525 openIndexPackage After this CL, it issued: 19 IsDirWithGoFiles 7 Lstat 60 Open 606 ReadDir 256 Stat 7 Walk 3 indexModule 24 openIndexModule 525 openIndexPackage This speedup helps the Dragonfly builder, which has very slow file I/O and is timing out since a recent indexing change. Times for go test -run=Script/^work$ on the Dragonfly builder: 50s before indexing changes 31s full module indexing of std 46s per-package indexing of std It cuts the time for go test -run=Script/^work$ from 44s to 20s. For golang#53577. Change-Id: I7189a77fc7fdf61de3ab3447efc4e84d1fc52c25 Reviewed-on: https://go-review.googlesource.com/c/go/+/416134 Reviewed-by: Bryan Mills <bcmills@google.com>

For a large module, opening the index was populating tables with entries for every package in the module. If we are only using a small number of those packages, this is wasted work that can dwarf the benefit from the index. This CL changes the index reader to avoid loading all packages at module index open time. It also refactors the code somewhat for clarity. It also removes some duplication by defining that a per-package index is a per-module index containing a single package, rather than having two different formats and two different decoders. It also changes the string table to use uvarint-prefixed data instead of having to scan for a NUL byte. This makes random access to long strings more efficient - O(1) instead of O(n) - and can significantly speed up the strings.Compare operation in the binary search looking for a given package. Also add a direct test of the indexing code. For golang#53577. Change-Id: I7428d28133e4e7fe2d2993fa014896cd15af48af Reviewed-on: https://go-review.googlesource.com/c/go/+/416178 Reviewed-by: Bryan Mills <bcmills@google.com>

fsys.Walk is cloned from filepath.Walk, which has always handled a walk of a directory by reading the full directory before calling the callback on the directory itself. So if the callback returns fs.SkipDir, those entries are thrown away, but the expense of reading them was still incurred. (Worse, this is the expensive directory read that also calls Stat on every entry.) On machines with slow file system I/O, these reads are particularly annoying. For example, if I do go list m... there is a call to filepath.Walk that is told about $GOROOT/src/archive and responds by returning filepath.SkipDir because archive does not start with m, but it only gets the chance to do that after the archive directory has been read. (Same for all the other top-level directories.) Even something like go list github.com/foo/bar/... reads every top-level $GOPATH/src directory. When we designed filepath.WalkDir, one of the changes we made was to allow calling the callback twice for a directory: once before reading it, and then possibly again if the read produces an error (uncommon). This CL changes fsys.Walk to use that same model. None of the callbacks need changing, but now the $GOROOT/src/archive and other top-level directories won't be read when evaluating a pattern like 'm...'. For golang#53577. Fixes golang#53765. Change-Id: Idfa3b9e2cc335417bfd9d66dd584cb16f92bd12e Reviewed-on: https://go-review.googlesource.com/c/go/+/416179 Run-TryBot: Russ Cox <rsc@golang.org> Reviewed-by: Bryan Mills <bcmills@google.com> TryBot-Result: Gopher Robot <gobot@golang.org>

The gccgo compiler does not load standard-library packages from GOROOT/src, so we cannot load those packages from the GOROOT/src index when using that compiler. This fixes TestScript/gccgo_link_c (and perhaps other gccgo tests) when a 'gccgo' executable is present. Unfortunately, only a few builders caught the broken test because 'gccgo' is not installed on most Go project builders (see golang#35786). For golang#53577. Fixes golang#53815. Change-Id: I11a5cf6dbf4ac9893c4d02bd6ab7ef60f67b1e87 Reviewed-on: https://go-review.googlesource.com/c/go/+/417094 TryBot-Result: Gopher Robot <gobot@golang.org> Run-TryBot: Bryan Mills <bcmills@google.com> Reviewed-by: Russ Cox <rsc@golang.org>

bcmills added OS-Dragonfly NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. GoCommand cmd/go labels Jun 27, 2022

bcmills added this to the Go1.19 milestone Jun 27, 2022

bcmills mentioned this issue Jun 28, 2022

cmd/go: frequent test timeouts on dragonfly-amd64 builder #45215

Closed

gopherbot closed this as completed in golang/build@c6075b8 Aug 2, 2022

golang locked and limited conversation to collaborators Aug 2, 2023

gopherbot added the FrozenDueToAge label Aug 2, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

cmd/go: tests frequently timing out on `dragonfly-amd64` since CL 412394 #53577

cmd/go: tests frequently timing out on `dragonfly-amd64` since CL 412394 #53577

bcmills commented Jun 27, 2022

gopherbot commented Jun 27, 2022

gopherbot commented Jul 5, 2022

gopherbot commented Jul 6, 2022

gopherbot commented Jul 6, 2022

gopherbot commented Jul 12, 2022

gopherbot commented Jul 22, 2022

cmd/go: tests frequently timing out on dragonfly-amd64 since CL 412394 #53577

cmd/go: tests frequently timing out on dragonfly-amd64 since CL 412394 #53577

Comments

bcmills commented Jun 27, 2022

gopherbot commented Jun 27, 2022

gopherbot commented Jul 5, 2022

gopherbot commented Jul 6, 2022

gopherbot commented Jul 6, 2022

gopherbot commented Jul 12, 2022

gopherbot commented Jul 22, 2022

cmd/go: tests frequently timing out on `dragonfly-amd64` since CL 412394 #53577

cmd/go: tests frequently timing out on `dragonfly-amd64` since CL 412394 #53577