cmd/go: test cached run slower than real test run

[dbentley]

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

1.10.3

Does this issue reproduce with the latest release?

Yes.

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

linux; amd64

What did you do?

go test --count 1 .; time go test .

foo_test.go:
// package and imports snipped
func TestCache(t testing.T) {
tmp := os.TempDir()
for i := 0; i < 101000*1000; i++ {
os.Stat(filepath.Join(tmp, fmt.Sprintf("%d", i)))
}
}

What did you expect to see?

$ go test --count 1 .; time go test .
ok github.com/dbentley/testcache 11.839s
ok github.com/dbentley/testcache (cached)

real 2s

What did you see instead?

$ go test --count 1 .; time go test .
ok github.com/dbentley/testcache 11.839s
ok github.com/dbentley/testcache (cached)

real 1m2.278s

Further investigation

Using GODEBUG=gocachetest=1 or GODEBUG=gocachehash=1 doesn't cause output for 30+s.

I think the function inDir (currently at https://github.com/golang/go/blob/master/src/cmd/go/internal/test/test.go#L1450 ) evaluates symlinks, which requires lots of stat'ing.

It looks like this was introduced in 37d5627

[ianlancetaylor]

Agreed. On my laptop, running this test program:

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 < 1000*1000; i++ {
		os.Stat(filepath.Join(tmp, fmt.Sprintf("%d", i)))
	}
}

I see this:

> time go test -test.count=1 ~/foo_test.go
ok  	command-line-arguments	1.746s

real	0m1.931s
user	0m0.796s
sys	0m1.272s
> time go test ~/foo_test.go
ok  	command-line-arguments	(cached)

real	0m5.260s
user	0m3.392s
sys	0m2.328s

In other words, the cached run actually takes longer than the real run.

We may need a symlink cache. Or maybe it's something else, I'm not sure.

[rsc]

Or we should just drop that whole symlink thing there. I don't see the point of evaluating symlinks in inDir.

[rsc]

Also the test input list should filter those out when recorded, not each time it is used.

[gopherbot]

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

[gopherbot]

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

[gopherbot]

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

[bcmills]

On https://golang.org/cl/127818, @rsc says:

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.

[maiamcc]

This reproduces for me on go1.16 darwin/amd64 -- any update on when this will be fixed?

[bcmills]

@maiamcc, this issue is milestoned Unplanned and tagged “help wanted“. To my knowledge, no one is actively working on it at the moment.

[bcmills]

On #50775, @millerresearch notes:

Computing the TestInputsID takes a stupendously long time because it's going through a testlog.txt which lists 357000 filenames, each requiring a stat call after being expanded by filepath.EvalSymlinks (which itself requires a stat call per filename component). In fact there are only 5841 unique lines in the testlog.txt, so sorting the list and eliminating duplicates would speed that up quite a bit.

That sounds like delightfully low-hanging fruit.

[matthewmueller]

I've been struggling with this issue. The last place you think to look is go test itself. When I kill -ABRT <pid>, it does seem to be getting stuck in internal symlink libraries. Not very scientific, but I've seen my 30s tests take 15m.

@bcmills it does seem like this deduping has been tried already: #26732, or at least not computing caches so many times. There might be something helpful in that PR.

[ianlancetaylor]

@bcmills @matloob This issue is marked for 1.19. Should it move to Backlog?

[bcmills]

I've got a cluster of test-caching issues that I'd like to get to in the near future, but given scheduling constraints probably not until 1.21. Backlog it is for now.