cmd/go, testing: go test 4-5x slower on Windows when test caching is used; -count=1 is fast #72992
Comments
|
maybe #35801 |
gabyhelp
added
the
BugReport
qmuntal
added
OS-Windows
NeedsInvestigation
|
Odd, I can't clone the repo at all on Windows: |
|
Your git install may not have long paths enabled; the Windows GUI installer I think preselects the option but some installs might not. (Apologies for the terribly long test names; they're autogenerated and used to "fit" before we started using the repo as a submodule...) |
|
Thanks, I'll give that a try. FWIW, I can reproduce this on Linux, but the delta is less extreme at ~2x: 24s vs 12s |
|
Oh, wow, I guess my internal clock never noticed. $ go clean -testcache
$ time go test ./internal/testrunner
ok github.com/microsoft/typescript-go/internal/testrunner 8.609s
go test ./internal/testrunner 108.22s user 23.12s system 892% cpu 14.709 total
$ time go test -count=1 ./internal/testrunner
ok github.com/microsoft/typescript-go/internal/testrunner 8.919s
go test -count=1 ./internal/testrunner 106.11s user 20.10s system 1292% cpu 9.763 totalNot quite as pronounced on my machine but I guess I couldn't tell 9 seconds from 14 seconds. |
|
I managed to reproduce on a gotip-windows-amd64 gomote by setting There I get 110s vs 16s. |
|
Back to Linux, looking at system calls via strace. Here are the syscall counts with And with caching: The caching version makes 10x as many newfstatat calls. My guess would be that FS calls are more expensive on Windows, making the issue more pronounced. |
|
I collected strace logs with: And filtered to newfstatat arguments with: Just eyeballing the diff, the cache version add fstat calls for lots of stuff (everything?) in Most of the files are stat'd more than once. I didn't do an explicit count to see if that adds up to all of the difference. Presumably the test must be opening these files or they wouldn't be part of the cache key, so perhaps it is the multiple calls that is the problem? I'll leave it here for the cmd/go folks. |
Yeah, the tests definitely open these files; they are opened, read out, and then are used to generate more subtests. Which tests are generated (unfortunately) depend on what's in those files too, though that wouldn't contribute to more stat calls specifically I wouldn't think... |
|
Right, to be clear my line of thinking is that even if cmd/go stating these files is slow, since the test itself opens and reads them, you’d expect the test to be slower than cmd/go. Do the tests run in parallel? That may be a difference from cmd/go. |
|
They run in parallel, but I don't think they are initially scanned/read in parallel (i.e. it's |
|
Some additional details from #72992 (comment): This is the number of times each path is stat'd. The top four, with 170k+ stats each, are empty directories. I'm not sure what's up with that. Here is the full distribution: ~5k unique paths are stat'd once, ~200k 3 times, ~12k 6 times, and ~151k 7 times. |
|
Just for reference, this package contains 78291 tests (according to the count of |
Go version
go version go1.24.1 windows/amd64
Output of
go envin your module/workspace:What did you do?
These tests come from the Go port of The TypeScript compiler. We've found that on Windows only, the Go test cache seems to make things a lot slower (microsoft/typescript-go#685 disables it for Windows for now).
What did you see happen?
On my machine, the test run after cleaning the test cache takes 13 to run the tests, but the wall time is 65 seconds:
What did you expect to see?
Tunning with
-count=1(skipping all test caching), the actual test time is about the same, but the wall time is only 15 seconds, about 4-5x faster:This doesn't reproduce on Linux.
The text was updated successfully, but these errors were encountered: