cmd/go: "go test" seems to cache test build output when GODEBUG changes

[mvdan]

I was using GODEBUG=inittrace=1 to get some quick stats on the init cost of some packages via go test, and I noticed that even after I unset the variable, its output was still around - presumably via Go's cache.

As a repro:

$ go version
go version devel go1.19-c6d9b38dd8 Wed Mar 9 06:51:37 2022 +0000 linux/amd64
$ cd $(go env GOROOT)/src/encoding/json
$ GODEBUG=inittrace=1 go test -c -vet=off 2>&1 | wc -l
625
$ go test -c -vet=off 2>&1 | wc -l
488

It's unclear why the number of lines diminishes, but they're all still inittrace output.

go build does not show this bug, so presumably the bug is with the test cache:

$ GODEBUG=inittrace=1 go build 2>&1 | wc -l
137
$ go build 2>&1 | wc -l
0

Perhaps Go's cache should be taught to include GODEBUG as part of cache key hashes.

[mvdan]

Slight correction: I don't think it's the test cache, because go clean -testcache did not fix the glitch. go clean -cache did.

[dr2chase]

Curious if the fix would just be to add GODEBUG to the list in cmd/go/internal/work/exec.go:

		magic := []string{
			"GOCLOBBERDEADHASH",
			"GOSSAFUNC",
			"GOSSADIR",
			"GOSSAHASH",
		}

[dr2chase]

@bcmills, @ianlancetaylor , y'all are the nominal owners.
I think the assertion is that if GODEBUG is present, someone probably wants to run the compiler and not use cached results.

[bcmills]

To my recollection, GODEBUG is not supposed to change the compiler's output — only the run-time behavior of the resulting program.

So it seems to me that go test should invalidate the output of the test run when GODEBUG changes, but not the build steps leading up to it.

[bcmills]

(If the purpose of GODEBUG is to cause the compiler to emit some side-output to stdout or stderr, this may be a duplicate of #27628.)

[ianlancetaylor]

This case is confusing, because GODEBUG=inittrace=1 is going to affect the cmd/go program itself, and the compiler, and the linker, and the actual run of the test program.

I think I agree with @dr2chase that we should make GODEBUG part of the build action ID, and we should also make it part of the test run action ID if it isn't already.

[mvdan]

This case is confusing, because GODEBUG=inittrace=1 is going to affect the cmd/go program itself, and the compiler, and the linker, and the actual run of the test program.

That probably explains why my cached run had fewer output lines: that included the cached output from toolchain programs like the compiler, but not the top-level cmd/go process.

Note that I used -c in my example on purpose, to at least remove "run of the test program" from the equation.

[leitzler]

FWIW, seems like this isn't isolated to tests. As per go version devel go1.21-9222a01e65 Fri Feb 3 04:37:17 2023 +0000 darwin/arm64:

% cd $(mktemp -d)
% go mod init x
go: creating new go.mod: module x
% cat > main.go <<EOF
heredoc> package main
heredoc>
heredoc> func main() {}
heredoc> EOF

% GODEBUG=inittrace=1 go run .
init internal/bytealg @0 ms, 0 ms clock, 0 bytes, 0 allocs
init runtime @0.033 ms, 0.085 ms clock, 0 bytes, 0 allocs
init errors @0.41 ms, 0.003 ms clock, 0 bytes, 0 allocs
[...]

% go run .
# x
init internal/bytealg @0.002 ms, 0 ms clock, 0 bytes, 0 allocs
init runtime @0.015 ms, 0.023 ms clock, 0 bytes, 0 allocs
init errors @0.15 ms, 0.001 ms clock, 0 bytes, 0 allocs
[...]

I would expect GODEBUG to only affecting runtime.

[bcmills]

@leitzler, the issue with go run is probably separate (#27628).

[leitzler]

Thanks Bryan! I did see that one but skipped reading through it since it seemed to be related to the usage of -toolexec.