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,testing,doc: better information about debugging test cache failures #35301

kevinburke opened this issue Nov 1, 2019 · 6 comments
help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.


Copy link

I'm trying to figure out why Go is not caching a test I wrote. First, after about 10-15 minutes of searching (including through old issues here) I could not find the flag to enable the debug output that shows you how Go builds its cache. Finally, I found it (GODEBUG=gocache{hash,test}=1)

I am trying to read through the output of gocachehash=1 but it's still not easy to figure out what is going wrong. The obvious first thing to do is to run the tests twice and then diff the output and see what's different. However, the output (about 10,000 lines) from two gocachehash runs prints out in different order each time so the diff is very large.

Next I tried sorting each output file and printing it. This yields a pretty manageable diff.

< --- PASS: TestZipServed (0.08s)
> --- PASS: TestZipServed (0.07s)
< HASH /Users/kevin/Library/Caches/go-build/07/076863ca534c50cc9e8a07b4a34b9ace144717479540c5554dae6736e55cb97e-d: 076863ca534c50cc9e8a07b4a34b9ace144717479540c5554dae6736e55cb97e
> HASH /Users/kevin/Library/Caches/go-build/2d/2d26f8ed83dc6de73bc9496e28d0e378ec6945d8641b2016bae22f9c0ddb929b-d: 2d26f8ed83dc6de73bc9496e28d0e378ec6945d8641b2016bae22f9c0ddb929b
< HASH /Users/kevin/Library/Caches/go-build/37/376397066f40ef1fac96c02af9c4a0699a0e5aa019bc41dafa3d93954e7fe7c8-d: 376397066f40ef1fac96c02af9c4a0699a0e5aa019bc41dafa3d93954e7fe7c8
> HASH /Users/kevin/Library/Caches/go-build/af/af711140c05b585b7bf422b3d109876cfa289b0551b3933d9c8b25ac5166b24c-d: af711140c05b585b7bf422b3d109876cfa289b0551b3933d9c8b25ac5166b24c
< HASH /Users/kevin/Library/Caches/go-build/bb/bbffa5c817822dfef6bfc0da140b7a660f2c606658e504c66219c9b99d544bfd-d: bbffa5c817822dfef6bfc0da140b7a660f2c606658e504c66219c9b99d544bfd
> HASH /Users/kevin/Library/Caches/go-build/cc/cc58b0a1ebc54513f2062ad23b50ae86906345c8c01f85423ac1a3f401e71b91-d: cc58b0a1ebc54513f2062ad23b50ae86906345c8c01f85423ac1a3f401e71b91
> HASH /Users/kevin/Library/Caches/go-build/d7/d7f61ad9a5bd0b6f79299046b000f58a46489414bfd56724d1359d150532fd6d-d: d7f61ad9a5bd0b6f79299046b000f58a46489414bfd56724d1359d150532fd6d
> HASH /Users/kevin/Library/Caches/go-build/db/dbf620d8019f251ec68ba6d82177b3d3f8db4e5c08f0d7021e6db57f1326075a-d: dbf620d8019f251ec68ba6d82177b3d3f8db4e5c08f0d7021e6db57f1326075a
< HASH /var/folders/s1/909yt58s4wj8h_7v7frr8rkm0000gn/T/go-build401879888/b001/_testmain.go: 20eb5f28897c44000e3a30317c33d3c9a8c3c2a3e6e76c1efeaaca21a18e5e62
> HASH /var/folders/s1/909yt58s4wj8h_7v7frr8rkm0000gn/T/go-build828546655/b001/_testmain.go: 20eb5f28897c44000e3a30317c33d3c9a8c3c2a3e6e76c1efeaaca21a18e5e62
< HASH[open]: "stat 1476 1a4 2019-11-01 04:46:46.985735425 +0000 UTC false\n"
> HASH[open]: "stat 1476 1a4 2019-11-01 04:46:55.122015265 +0000 UTC false\n"
< ok	1.113s
> ok	1.111s

I repeated the same exercise with a test that printed out (cached) to compare. The cached test diff also had HASH ... /T/go-build lines so I assume those are a red herring. That essentially leaves this diff:

< HASH[open]: "stat 1476 1a4 2019-11-01 04:46:46.985735425 +0000 UTC false\n"
> HASH[open]: "stat 1476 1a4 2019-11-01 04:46:55.122015265 +0000 UTC false\n"

However I am confused by this one as well because the content hash of the opened file is identical, so I'm not sure why Go is refusing to use the test cache.

Am I correct that these "stat" lines are the reason Go is not caching the result of this test? If so, what is the problem that is leading Go to not cache the results?

Can we build a tool to automate the process of debugging test hashes? E.g. run a test twice, capture the output, sort it, print the lines that differ.

Copy link

Yes, it's the stat lines. The modification time of the file has changed. The test hash, unlike gobuild, is not purely content based.

Copy link
Contributor Author

Ah, okay, that's frustrating but fair enough.

Maybe this is worth posting a second ticket about. I have a test that generates configuration files in the testdata directory. I want to check in the files to Git so that I can see when a change to the code generates a change to the configuration files. The test writes the templates to disk each time, even if the file contents don't change. So even though the contents aren't changing, the mtimes are changing, which means the tests are running every time.

Would it work to walk the file tree and set the mtime of every file after writing it, to a constant value? Alternatively it would be nice to have a hook to say "you can ignore changes to this file when computing the build cache" but maybe that is a Pandora's box we don't want to open.

Copy link

Can you change the test to write to a temporary file and only update the real file if the temporary file is different? I'm actually not completely confident that that would permit caching, but it might.

@FiloSottile FiloSottile added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Nov 5, 2019
@FiloSottile FiloSottile added this to the Unplanned milestone Nov 5, 2019
Copy link
Contributor Author

In this particular case it turns out the test cache is not being written because there's a file in there with a modification time that is too recent. The file name doesn't print out because the file name prints out after the stat line.

Copy link

zimmski commented Jun 8, 2022

(Please let me know if commenting here is the wrong move, i will create an issue then)

Currently trying to debug why our Go unit tests are not completely cached when retrying a CI pipeline. Stumbled over this issue because i find cache-misses hard to debug as well.

Discoverability of the current debug features could be easily improved by extending some texts. There are some problems related to the documentation:

  • Reading through go help test i read If a run of go test has any test or non-test flags outside this set, the result is not cached.. Which is odd because we are using "-vet=off" which is not listed in the strictly cacheable-options. Hence, i am wondering if the listed options needs to be updated, or if they can be auto-generated.
  • I was then wondering how to debug misses. It is not documented in "go help test", so adding that there would help someone who does not know about GODEBUG
  • After that i opened up because that is my usual go-to for GODEBUG documentation. There is nothing about the go test cache there though. Which was odd.
  • Next i thought, there is surely something on but it isn't.
  • At this point i was really wondering if there is a debug-option at all. So i went to look at the source code found then which showed me that there is a GODEBUG value, no there are even three!
  • I googled one of them with "" to make sure i only hit the official documentation. Gave me which showed me that "go help cache" exists. Which is a GREAT documentation. And one could argue that i should just grepped "go help" for "cache" and then found it. I am however arguing here that adding at least a hint to "go help test" and the "testing" package on where to find the information on "caching" would improve the discoverability greatly.

I gave GODEBUG=gocachetest=1 a whirl and it seems to me that at least that output is hard to debug:

  • I see that there are some test-ids that match -> they are cached, great
  • There are lots of entries about "test output not found: cache entry not found" but there is no reason why they are missing even though i executed the same CI job just a few minutes earlier, i only pressed "retry".
  • Then i saw that there are some "file used as input is too new" in between, and i guess those are the problem.

That is my user experience so far with debugging test cache misses.

So the next thing what i am wondering is i guess why Go files are cached on their content but these used input files are not? I am wondering the same thing as #35301 (comment) i guess.

Copy link

or-shachar commented Nov 27, 2023

Tackling this issue myself now. With the new gocacheprog capability - understanding how tests are cached becomes critical for us.

I think that one thing that can really help is if we can print the full line of testlog/cache data in computeTestInputsID. Currently it only prints it if it's malformed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
None yet

No branches or pull requests

5 participants