cmd/go,testing,doc: better information about debugging test cache failures

kevinburke commented 5 years ago

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.

1c1
< --- PASS: TestZipServed (0.08s)
---
> --- PASS: TestZipServed (0.07s)
5d4
< HASH /Users/kevin/Library/Caches/go-build/07/076863ca534c50cc9e8a07b4a34b9ace144717479540c5554dae6736e55cb97e-d: 076863ca534c50cc9e8a07b4a34b9ace144717479540c5554dae6736e55cb97e
13a13
> HASH /Users/kevin/Library/Caches/go-build/2d/2d26f8ed83dc6de73bc9496e28d0e378ec6945d8641b2016bae22f9c0ddb929b-d: 2d26f8ed83dc6de73bc9496e28d0e378ec6945d8641b2016bae22f9c0ddb929b
18d17
< HASH /Users/kevin/Library/Caches/go-build/37/376397066f40ef1fac96c02af9c4a0699a0e5aa019bc41dafa3d93954e7fe7c8-d: 376397066f40ef1fac96c02af9c4a0699a0e5aa019bc41dafa3d93954e7fe7c8
41a41
> HASH /Users/kevin/Library/Caches/go-build/af/af711140c05b585b7bf422b3d109876cfa289b0551b3933d9c8b25ac5166b24c-d: af711140c05b585b7bf422b3d109876cfa289b0551b3933d9c8b25ac5166b24c
44d43
< HASH /Users/kevin/Library/Caches/go-build/bb/bbffa5c817822dfef6bfc0da140b7a660f2c606658e504c66219c9b99d544bfd-d: bbffa5c817822dfef6bfc0da140b7a660f2c606658e504c66219c9b99d544bfd
46a46
> HASH /Users/kevin/Library/Caches/go-build/cc/cc58b0a1ebc54513f2062ad23b50ae86906345c8c01f85423ac1a3f401e71b91-d: cc58b0a1ebc54513f2062ad23b50ae86906345c8c01f85423ac1a3f401e71b91
50a51
> HASH /Users/kevin/Library/Caches/go-build/d7/d7f61ad9a5bd0b6f79299046b000f58a46489414bfd56724d1359d150532fd6d-d: d7f61ad9a5bd0b6f79299046b000f58a46489414bfd56724d1359d150532fd6d
52a54
> HASH /Users/kevin/Library/Caches/go-build/db/dbf620d8019f251ec68ba6d82177b3d3f8db4e5c08f0d7021e6db57f1326075a-d: dbf620d8019f251ec68ba6d82177b3d3f8db4e5c08f0d7021e6db57f1326075a
1366c1368
< 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
7518c7520
< 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"
10467c10469
< ok    github.com/example/project/src/package  1.113s
---
> ok    github.com/example/project/src/package  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.

ianlancetaylor commented 5 years ago

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

kevinburke commented 4 years ago

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.

ianlancetaylor commented 4 years ago

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.

kevinburke commented 4 years ago

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.

zimmski commented 2 years ago

(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 https://pkg.go.dev/runtime 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 https://pkg.go.dev/testing 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 https://go.dev/src/cmd/go/internal/cache/ then https://go.dev/src/cmd/go/internal/cache/cache.go which showed me that there is a GODEBUG value, no there are even three!
I googled one of them with "site:pkg.go.dev" to make sure i only hit the official documentation. Gave me https://pkg.go.dev/cmd/go/internal/help 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 https://github.com/golang/go/issues/35301#issuecomment-548870904 i guess.

or-shachar commented 11 months ago

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.

golang / go

cmd/go,testing,doc: better information about debugging test cache failures #35301