cmd/go: cache hit takes too long on a test that opens many files #26726

ijt · 2018-07-31T20:12:08Z

What version of Go are you using (`go version`)?

go1.10.2

Does this issue reproduce with the latest release?

Yes.

ijt$ time go1.11beta1 test .                                                                                                                                                                                                                                                                                                 
ok      github.com/google/go-cloud/wire/internal/wire   38.037s

real    1m10.576s
user    1m22.899s
sys     0m52.377s
ijt$ time go1.11beta1 test .
ok      github.com/google/go-cloud/wire/internal/wire   (cached)

real    0m30.822s
user    0m11.384s
sys     0m20.135s

What operating system and processor architecture are you using (`go env`)?

GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/issactrotts/Library/Caches/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/issactrotts/gopath"
GORACE=""
GOROOT="/Users/issactrotts/homebrew/Cellar/go/1.10.2/libexec"
GOTMPDIR=""
GOTOOLDIR="/Users/issactrotts/homebrew/Cellar/go/1.10.2/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/9z/3vhqmj_j18v6vsk1q2jr486r001n0v/T/go-build330802734=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

m=github.com/google/go-cloud
go get $m
cd $(go list -f '{{.Dir}}' $m)
cd wire/internal/wire
# Run tests once.
time go test -v .
# Run tests again. This time the result is cached, but it still takes over 30s on a 2015 Macbook pro laptop.
time go test -v .

What did you expect to see?

The second test run should have taken under 1s since nothing changed.

What did you see instead?

It took over 30s.

@zombiezen suggested that the slowness arises from the wire tests opening many packages under $GOROOT for type checking, making go test spend a lot of time checking their hashes when deciding whether there is a cache hit.

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

mvdan · 2018-07-31T20:34:38Z

Perhaps related to #26562.

ijt · 2018-07-31T22:26:23Z

I ran it again like this

GODEBUG=gocachehash=1 go test .

and the output seems to say that the same hashes are being recomputed many times.

...
HASH[getenv]
HASH[getenv]: "go1.10.3"
HASH[getenv]: "\x00"
HASH[getenv]: 213baadbc0781c1584c3a372b0c954145a41421235ba99e327ec0dd4f2326471
HASH[testInputs]: "env TMPDIR 213baadbc0781c1584c3a372b0c954145a41421235ba99e327ec0dd4f2326471\n"
HASH[getenv]
HASH[getenv]: "go1.10.3"
HASH[getenv]: "\x00"
HASH[getenv]: 213baadbc0781c1584c3a372b0c954145a41421235ba99e327ec0dd4f2326471
HASH[testInputs]: "env TMPDIR 213baadbc0781c1584c3a372b0c954145a41421235ba99e327ec0dd4f2326471\n"
HASH[getenv]
HASH[getenv]: "go1.10.3"
HASH[getenv]: "\x00"
HASH[getenv]: 213baadbc0781c1584c3a372b0c954145a41421235ba99e327ec0dd4f2326471
HASH[testInputs]: "env TMPDIR 213baadbc0781c1584c3a372b0c954145a41421235ba99e327ec0dd4f2326471\n"
HASH[getenv]
HASH[getenv]: "go1.10.3"
HASH[getenv]: "\x00"
HASH[getenv]: 213baadbc0781c1584c3a372b0c954145a41421235ba99e327ec0dd4f2326471
HASH[testInputs]: "env TMPDIR 213baadbc0781c1584c3a372b0c954145a41421235ba99e327ec0dd4f2326471\n"
HASH[getenv]
HASH[getenv]: "go1.10.3"
HASH[getenv]: "\x00"
HASH[getenv]: 213baadbc0781c1584c3a372b0c954145a41421235ba99e327ec0dd4f2326471
HASH[testInputs]: "env TMPDIR 213baadbc0781c1584c3a372b0c954145a41421235ba99e327ec0dd4f2326471\n"
HASH[testInputs]: 5650a478a2695895ea5dad0d10e315fe75f5d25b69bd3e0a20012a2c5adf2548
HASH subkey 422e11c5f77c95dbb5a70bf9d3f8cb86c84e52ac80a14030b5622b2fed39ed70 "inputs:5650a478a2695895ea5dad0d10e315fe75f5d25b69bd3e0a20012a2c5adf2548" = e3e7ae218e3b146458d106618002b8e7b2dbad22e5e8fd295d858549b0ac9ec0
ok      github.com/google/go-cloud/wire/internal/wire   (cached)

It looks like the check could be sped up a lot by only computing the hashes once.

Before this change, the same hashes were being computed multiple times in some cases. This gets the case reported in issue golang#26726 down from over 30s to .8s.

gopherbot · 2018-08-01T02:51:00Z

Change https://golang.org/cl/127155 mentions this issue: cmd/go: check test cache more efficiently

ijt · 2018-08-02T01:44:04Z

I instrumented vgo test and got this output from go tool pprof:

It shows that the inDir function takes up most of the time.

ijt · 2018-08-02T01:53:07Z

That lends support to the idea raised in issue #26562 that the slowdown was introduced in 37d5627.

ijt · 2018-08-02T02:01:41Z

Simplifying inDir to no longer call EvalSymlinks fixes the speed problem.

diff --git a/vendor/cmd/go/internal/test/test.go b/vendor/cmd/go/internal/test/test.go
index aff5ff2..02fc6cc 100644
--- a/vendor/cmd/go/internal/test/test.go
+++ b/vendor/cmd/go/internal/test/test.go
@@ -1429,15 +1429,7 @@ func computeTestInputsID(a *work.Action, testlog []byte) (cache.ActionID, error)
 }
 
 func inDir(path, dir string) bool {
-       if str.HasFilePathPrefix(path, dir) {
-               return true
-       }
-       xpath, err1 := filepath.EvalSymlinks(path)
-       xdir, err2 := filepath.EvalSymlinks(dir)
-       if err1 == nil && err2 == nil && str.HasFilePathPrefix(xpath, xdir) {
-               return true
-       }
-       return false
+       return str.HasFilePathPrefix(path, dir)
 }

The question is how to do it without giving up correctness.

mvdan · 2018-08-02T06:59:51Z

The symlink issue is being fixed in #26562 already.

gopherbot · 2018-08-02T17:29:24Z

Change https://golang.org/cl/127635 mentions this issue: cmd/go: no longer eval symlinks in inDir

ijt · 2018-08-02T20:07:49Z

Closing this as a duplicate of #26562.

Evaluating the symlinks was slowing down test cache checks. Fixes #26562 Fixes #26726 ijt:~/gopath/src/issue26562$ cat foo_test.go package foo_test import ( "fmt" "os" "path/filepath" "testing" ) // package and imports snipped func TestCache(t *testing.T) { tmp := os.TempDir() for i := 0; i < 1000000; i++ { os.Stat(filepath.Join(tmp, fmt.Sprintf("%d", i))) } } ijt:~/gopath/src/issue26562$ time ~/github/go/bin/go test -count=1 PASS ok issue26562 9.444s real 0m10.021s user 0m2.344s sys 0m7.835s ijt:~/gopath/src/issue26562$ time ~/github/go/bin/go test . ok issue26562 (cached) real 0m0.802s user 0m0.551s sys 0m0.306s Change-Id: I3ce7f7b68bb5b9e802069f277e79e1ed3c162622 Reviewed-on: https://go-review.googlesource.com/127635 Run-TryBot: Ian Lance Taylor <iant@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Ian Lance Taylor <iant@golang.org>

gopherbot · 2018-08-03T01:18:34Z

Change https://golang.org/cl/127715 mentions this issue: cmd/go: revert "cmd/go: no longer eval symlinks in inDir"

It breaks on the Darwin builders, with --- FAIL: TestTestCacheInputs (21.65s) go_test.go:5371: file.txt: old=2018-08-02 15:12:21.136438 -0700 PDT m=+219.458659208, info.ModTime=2018-08-02 15:12:21 -0700 PDT go_test.go:5377: running testgo [test testcache] go_test.go:5377: standard output: go_test.go:5377: ok testcache 0.013s go_test.go:5378: running testgo [test testcache] go_test.go:5378: standard output: go_test.go:5378: ok testcache (cached) go_test.go:5382: running testgo [test testcache] go_test.go:5382: standard output: go_test.go:5382: ok testcache 0.172s go_test.go:5384: running testgo [test testcache] go_test.go:5384: standard output: go_test.go:5384: ok testcache (cached) go_test.go:5387: running testgo [test testcache -run=FileSize] go_test.go:5387: standard output: go_test.go:5387: ok testcache 0.012s go_test.go:5388: running testgo [test testcache -run=FileSize] go_test.go:5388: standard output: go_test.go:5388: ok testcache (cached) go_test.go:5391: running testgo [test testcache -run=FileSize] go_test.go:5391: standard output: go_test.go:5391: ok testcache 0.008s go_test.go:5393: running testgo [test testcache -run=FileSize] go_test.go:5393: standard output: go_test.go:5393: ok testcache (cached) go_test.go:5396: running testgo [test testcache -run=Chdir] go_test.go:5396: standard output: go_test.go:5396: ok testcache 0.417s go_test.go:5397: running testgo [test testcache -run=Chdir] go_test.go:5397: standard output: go_test.go:5397: ok testcache (cached) go_test.go:5400: running testgo [test testcache -run=Chdir] go_test.go:5400: standard output: go_test.go:5400: ok testcache (cached) go_test.go:5401: did not notice file size change go_test.go:5401: pattern $cached$ found unexpectedly in standard output FAIL Original CL description: Evaluating the symlinks was slowing down test cache checks. Fixes #26562 Fixes #26726 ijt:~/gopath/src/issue26562$ cat foo_test.go package foo_test import ( "fmt" "os" "path/filepath" "testing" ) // package and imports snipped func TestCache(t *testing.T) { tmp := os.TempDir() for i := 0; i < 1000000; i++ { os.Stat(filepath.Join(tmp, fmt.Sprintf("%d", i))) } } ijt:~/gopath/src/issue26562$ time ~/github/go/bin/go test -count=1 PASS ok issue26562 9.444s real 0m10.021s user 0m2.344s sys 0m7.835s ijt:~/gopath/src/issue26562$ time ~/github/go/bin/go test . ok issue26562 (cached) real 0m0.802s user 0m0.551s sys 0m0.306s Updates #26562 Updates #26726 Change-Id: I7914ee57dc75bcbd7f0ea01c70bed97d67c810ea Reviewed-on: https://go-review.googlesource.com/127715 Run-TryBot: Ian Lance Taylor <iant@golang.org> Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>

gopherbot · 2018-08-03T21:25:41Z

Change https://golang.org/cl/127818 mentions this issue: cmd/go: cache results of EvalSymlinks

rsc · 2018-10-25T15:19:25Z

I'd still really like to find a way to make the approach of CL 127635 - stop evaluating symlinks at all - work. I'll try to take a look in the next couple weeks.

bcmills · 2019-09-18T14:16:25Z

I'd still really like to find a way to make the approach of CL 127635 - stop evaluating symlinks at all - work.

If anyone wants to make another run at this, the description for CL 127715 includes the output of the failing test.

Fixes golang#26726 Change-Id: I94cae97f96debfb443ead647e6de35febfe95da3

gopherbot · 2023-07-21T10:57:31Z

Change https://go.dev/cl/511915 mentions this issue: cmd/go: cache results of EvalSymlinks

bcmills · 2023-12-13T20:37:00Z

I'm able to consistently reproduce this while trying to test a fix for #64702.

For golang#26726 Change-Id: Ic1499abf847f161206462d9238bb19cdeba302c3

gopherbot · 2024-02-13T09:17:48Z

Change https://go.dev/cl/563595 mentions this issue: cmd/go: change computeTestInputsID to use str.HasFilePathPrefix

ianlancetaylor added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jul 31, 2018

ianlancetaylor added this to the Go1.12 milestone Jul 31, 2018

ijt pushed a commit to ijt/go that referenced this issue Aug 1, 2018

cmd/go: uniq test log lines in computeTestInputsID

93cbf7b

Before this change, the same hashes were being computed multiple times in some cases. This gets the case reported in issue golang#26726 down from over 30s to .8s.

ijt mentioned this issue Aug 1, 2018

cmd/go: check test cache more efficiently #26732

Closed

ijt closed this as completed Aug 2, 2018

bradfitz reopened this Aug 3, 2018

bcmills added the ToolSpeed label Jan 18, 2019

bcmills modified the milestones: Go1.12, Go1.13 Jan 18, 2019

andybons modified the milestones: Go1.13, Go1.14 Jul 8, 2019

bcmills modified the milestones: Go1.14, Unplanned Sep 18, 2019

bcmills added the help wanted label Sep 18, 2019

qiulaidongfeng added a commit to qiulaidongfeng/go that referenced this issue Jul 21, 2023

cmd/go: cache results of EvalSymlinks

37cf29f

Fixes golang#26726 Change-Id: I94cae97f96debfb443ead647e6de35febfe95da3

qiulaidongfeng linked a pull request Jul 21, 2023 that will close this issue

cmd/go: cache results of EvalSymlinks #61498

Open

bcmills modified the milestones: Unplanned, Backlog Dec 13, 2023

bcmills added the GoCommand cmd/go label Dec 13, 2023

qiulaidongfeng added a commit to qiulaidongfeng/go that referenced this issue Feb 13, 2024

cmd/go: change computeTestInputsID to use str.HasFilePathPrefix

db47e77

For golang#26726 Change-Id: Ic1499abf847f161206462d9238bb19cdeba302c3

qiulaidongfeng mentioned this issue Feb 13, 2024

cmd/go: change computeTestInputsID to use str.HasFilePathPrefix #65690

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

cmd/go: cache hit takes too long on a test that opens many files #26726

cmd/go: cache hit takes too long on a test that opens many files #26726

ijt commented Jul 31, 2018

mvdan commented Jul 31, 2018

ijt commented Jul 31, 2018

gopherbot commented Aug 1, 2018

ijt commented Aug 2, 2018

ijt commented Aug 2, 2018 •

edited

ijt commented Aug 2, 2018

mvdan commented Aug 2, 2018

gopherbot commented Aug 2, 2018

ijt commented Aug 2, 2018

gopherbot commented Aug 3, 2018

gopherbot commented Aug 3, 2018

rsc commented Oct 25, 2018

bcmills commented Sep 18, 2019

gopherbot commented Jul 21, 2023

bcmills commented Dec 13, 2023

gopherbot commented Feb 13, 2024

cmd/go: cache hit takes too long on a test that opens many files #26726

cmd/go: cache hit takes too long on a test that opens many files #26726

Comments

ijt commented Jul 31, 2018

What version of Go are you using (go version)?

Does this issue reproduce with the latest release?

What operating system and processor architecture are you using (go env)?

What did you do?

What did you expect to see?

What did you see instead?

mvdan commented Jul 31, 2018

ijt commented Jul 31, 2018

gopherbot commented Aug 1, 2018

ijt commented Aug 2, 2018

ijt commented Aug 2, 2018 • edited

ijt commented Aug 2, 2018

mvdan commented Aug 2, 2018

gopherbot commented Aug 2, 2018

ijt commented Aug 2, 2018

gopherbot commented Aug 3, 2018

gopherbot commented Aug 3, 2018

rsc commented Oct 25, 2018

bcmills commented Sep 18, 2019

gopherbot commented Jul 21, 2023

bcmills commented Dec 13, 2023

gopherbot commented Feb 13, 2024

What version of Go are you using (`go version`)?

What operating system and processor architecture are you using (`go env`)?

ijt commented Aug 2, 2018 •

edited