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

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

Open
ijt opened this Issue Jul 31, 2018 · 12 comments

Comments

Projects
None yet
6 participants
@ijt
Contributor

ijt commented Jul 31, 2018

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.

@mvdan

This comment has been minimized.

Member

mvdan commented Jul 31, 2018

Perhaps related to #26562.

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

@ijt

This comment has been minimized.

Contributor

ijt commented Jul 31, 2018

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.

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

cmd/go: uniq test log lines in computeTestInputsID
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

This comment has been minimized.

gopherbot commented Aug 1, 2018

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

@ijt

This comment has been minimized.

Contributor

ijt commented Aug 2, 2018

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

screen shot 2018-08-01 at 6 35 11 pm

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

@ijt

This comment has been minimized.

Contributor

ijt commented Aug 2, 2018

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

@ijt

This comment has been minimized.

Contributor

ijt commented Aug 2, 2018

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

This comment has been minimized.

Member

mvdan commented Aug 2, 2018

The symlink issue is being fixed in #26562 already.

@gopherbot

This comment has been minimized.

gopherbot commented Aug 2, 2018

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

@ijt

This comment has been minimized.

Contributor

ijt commented Aug 2, 2018

Closing this as a duplicate of #26562.

@ijt ijt closed this Aug 2, 2018

gopherbot pushed a commit that referenced this issue Aug 2, 2018

cmd/go: no longer eval symlinks in inDir
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

This comment has been minimized.

gopherbot commented Aug 3, 2018

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

gopherbot pushed a commit that referenced this issue Aug 3, 2018

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>

@bradfitz bradfitz reopened this Aug 3, 2018

@gopherbot

This comment has been minimized.

gopherbot commented Aug 3, 2018

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

@rsc

This comment has been minimized.

Contributor

rsc commented Oct 25, 2018

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment