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: "go test" seems to cache test build output when GODEBUG changes #51561

Open
mvdan opened this issue Mar 9, 2022 · 11 comments
Open

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

mvdan opened this issue Mar 9, 2022 · 11 comments
Labels
GoCommand cmd/go NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@mvdan
Copy link
Member

mvdan commented Mar 9, 2022

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
Copy link
Member Author

mvdan commented Mar 9, 2022

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 dr2chase added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Mar 9, 2022
@dr2chase
Copy link
Contributor

dr2chase commented Mar 9, 2022

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
Copy link
Contributor

dr2chase commented Mar 9, 2022

@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
Copy link
Contributor

bcmills commented Mar 9, 2022

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
Copy link
Contributor

bcmills commented Mar 9, 2022

(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
Copy link
Contributor

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
Copy link
Member Author

mvdan commented Mar 10, 2022

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.

@seankhliao seankhliao added this to the Unplanned milestone Aug 20, 2022
@leitzler
Copy link
Contributor

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 bcmills added the GoCommand cmd/go label Feb 17, 2023
@bcmills bcmills modified the milestones: Unplanned, Backlog Feb 17, 2023
@bcmills
Copy link
Contributor

bcmills commented Feb 17, 2023

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

@leitzler
Copy link
Contributor

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

@bcmills
Copy link
Contributor

bcmills commented Feb 1, 2024

In #65436, @findleyr noted that the test output itself is also not affected by GODEBUG as it should be.

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.
Projects
None yet
Development

No branches or pull requests

6 participants