cmd/go: test cache hash inputs include ModTime, often causing cache misses on CI

[mvdan]

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]

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]

@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]

see also #22593

[mvdan]

@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]

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.