Skip to content
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: test cache hash inputs include ModTime, often causing cache misses on CI #58571

Open
mvdan opened this issue Feb 16, 2023 · 6 comments
Open
Labels
GoCommand cmd/go NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. ToolSpeed
Milestone

Comments

@mvdan
Copy link
Member

mvdan commented Feb 16, 2023

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

$ go version
go version devel go1.21-518889b35c Thu Feb 16 02:02:00 2023 +0000 linux/amd64

Does this issue reproduce with the latest release?

Yes, verified with Go 1.20.

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

go env Output
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/mvdan/.cache/go-build"
GOENV="/home/mvdan/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/mvdan/go/pkg/mod"
GONOPROXY="github.com/cue-unity"
GONOSUMDB="github.com/cue-unity"
GOOS="linux"
GOPATH="/home/mvdan/go"
GOPRIVATE="github.com/cue-unity"
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/mvdan/tip"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/mvdan/tip/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="devel go1.21-518889b35c Thu Feb 16 02:02:00 2023 +0000"
GCCGO="gccgo"
GOAMD64="v3"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/mvdan/src/nowt/go.mod"
GOWORK=""
CGO_CFLAGS="-O2 -g"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-O2 -g"
CGO_FFLAGS="-O2 -g"
CGO_LDFLAGS="-O2 -g"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build3213309622=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Many of the projects I contribute to use go test ./... on GitHub Actions. A majority of those also use GitHub's https://github.com/actions/cache to persist Go's GOCACHE and GOMODCACHE, so that consecutive CI runs should avoid much of the work if little code has changed.

This works for the most part, but I've noticed that commits which do not change any code at all (e.g. only modify the README) only show some packages as (cached), whereas other packages are always run from scratch. For example, see cue-lang/cue#2253.

After investigating quite a bit with GODEBUG=gocachehash=1 and its testInputs hashes, and reading through src/cmd/go/internal/test/test.go, I think the cause is modified times. Whenever a test opens a file, Go's automatic test caching tracks that file's path, file info, and contents to know whether it should re-run the test in the future. The file info includes the modified time:

func hashWriteStat(h io.Writer, info fs.FileInfo) {
	fmt.Fprintf(h, "stat %d %x %v %v\n", info.Size(), uint64(info.Mode()), info.ModTime(), info.IsDir())
}

Including the modified time may be needed for the test cache's own purposes, and in general it's not a problem when continuously developing on a machine. However, CI is a bit special: it's quite common to run in a temporary environment and start by fetching the code. In particular, the way GitHub Actions is used as CI tends to start with https://github.com/actions/checkout, which uses git clone to download the repository to a path like /home/runner/work/foobar/foobar. Note that the clone directory location does not change between runs; I first suspected that was the problem, but it is not.

The problem is that git does not store modified times in any way, and git clone creates new files when it's checking out a repository, so the cloned files end up having the current time as their modified time.

As a reproducer and demo, I've written https://github.com/mvdan/nowt/tree/master/test-cache-open-modtime. It contains a single Go test which opens a testdata file, and a script which reproduces the situation:

$ ./repro.bash 
Clone and test twice in a row, using the same directory and -trimpath. The test caching does not work.
-rw-r--r-- 1 mvdan mvdan 8 Feb 16 22:14 test-cache-open-modtime/testdata/foo.txt
ok  	mvdan.cc/nowt/test-cache-open-modtime	0.001s

-rw-r--r-- 1 mvdan mvdan 8 Feb 16 22:14 test-cache-open-modtime/testdata/foo.txt
ok  	mvdan.cc/nowt/test-cache-open-modtime	0.001s

The same again, but this time resetting the testdata file's mtime, since git clone otherwise sets it to the time it ran.
-rw-r--r-- 1 mvdan mvdan 8 Jan  1  2000 test-cache-open-modtime/testdata/foo.txt
ok  	mvdan.cc/nowt/test-cache-open-modtime	0.001s

-rw-r--r-- 1 mvdan mvdan 8 Jan  1  2000 test-cache-open-modtime/testdata/foo.txt
ok  	mvdan.cc/nowt/test-cache-open-modtime	(cached)

What did you expect to see?

I expected modified times to not affect Go's test caching hit vs miss decisions. Particularly since Go largely allows its developers to not be aware of modified times for incremental builds to work well, unlike other build systems like make.

What did you see instead?

The way most people use CI on popular platforms like GitHub Actions causes unnecessary Go test cache misses, and it's caused by modified times.

I could fix this for my projects by following each actions/checkout step with a script to walk all cloned files and reset their modified times to a static timestamp. However, that feels very unfortunate, and I imagine many Go users might not even notice that their CI is slower than it should be to begin with.

We could also try to convince third parties like git clone or actions/checkout to leave reproducible modified times on files, but I don't think that is likely to happen.

@seankhliao
Copy link
Member

seankhliao commented Feb 16, 2023

isn't this sort of necessary if go doesn't track the contents of external files?
eg if you modify testdata, without modtime it wouldn't know to rerun the test

@rittneje
Copy link

@mvdan Would it be possible for you to first run some script that sets the mtime of the relevant files to the last commit time of that file?

@seankhliao
Copy link
Member

see also #22593

@mvdan
Copy link
Member Author

mvdan commented Feb 17, 2023

@seankhliao You're right that any opened files don't currently get their content tracked in the test cache inputs:

	} else if info.Mode().IsRegular() {
		// Because files might be very large, do not attempt
		// to hash the entirety of their content. Instead assume
		// the mtime and size recorded in hashWriteStat above
		// are good enough.
		//
		// To avoid problems for very recent files where a new
		// write might not change the mtime due to file system
		// mtime precision, reject caching if a file was read that
		// is less than modTimeCutoff old.
		if time.Since(info.ModTime()) < modTimeCutoff {
			return cache.ActionID{}, errFileTooNew
		}
	}

However, I think that the logic is somewhat flawed and could be improved. For example, we're already getting the file information, so if a file is small (say, less than 256KiB), we could read and hash its contents rather than using its modified time for the cache input.

This would automatically solve almost all git clone problems I have with CI; the majority of the testdata files I use are plaintext and very small, like https://github.com/cue-lang/cue/blob/7d89acd5c44bca0c756f76089436ee9913818b03/cmd/cue/cmd/testdata/script/cmd_dir.txtar. Go's test cache would be less prone to unfortunate misses, and I don't think it would get noticeably slower.

Would it be possible for you to first run some script that sets the mtime of the relevant files to the last commit time of that file?

I could, yes, but having to do that for every project is quite a lot of work. Plus, I didn't even notice that CI on multiple of my projects was slow due to this bug for years. I think it's unfortunate for Go's test cache to not work well on CI systems by default.

There's also the problem with scripting CI in general. The majority of these projects test on Linux, Mac, and Windows. Even writing a POSIX Shell or Bash script to run on all of these is rather tricky.

@bcmills bcmills added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. GoCommand cmd/go labels Feb 17, 2023
@bcmills bcmills added this to the Backlog milestone Feb 17, 2023
@bcmills
Copy link
Contributor

bcmills commented Feb 17, 2023

We could also try to convince third parties like git clone or actions/checkout to leave reproducible modified times on files, but I don't think that is likely to happen.

It looks like there is a third-party git-restore-mtime tool (written in Python, which I would think would be portable enough) that does the obvious thing — setting the mtime to match the last author timestamp or commit timestamp of each file. But I agree that it would be better not to rely on that, since there are all kinds of ways an mtime may be changed.

@oschwald
Copy link

We looked at using git-restore-mtime for our CI, but that script is quite slow, wiping out many of the benefits of caching. We are currently using a modified version of this script that improves the handling of directories.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
GoCommand cmd/go NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. ToolSpeed
Projects
None yet
Development

No branches or pull requests

5 participants