cmd/go, testing: go test 4-5x slower on Windows when test caching is used; -count=1 is fast

[jakebailey]

Go version

go version go1.24.1 windows/amd64

Output of go env in your module/workspace:

set AR=ar
set CC=gcc
set CGO_CFLAGS=-O2 -g
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-O2 -g
set CGO_ENABLED=1
set CGO_FFLAGS=-O2 -g
set CGO_LDFLAGS=-O2 -g
set CXX=g++
set GCCGO=gccgo
set GO111MODULE=
set GOAMD64=v1
set GOARCH=amd64
set GOAUTH=netrc
set GOBIN=
set GOCACHE=C:\Users\jabaile\AppData\Local\go-build
set GOCACHEPROG=
set GODEBUG=
set GOENV=C:\Users\jabaile\AppData\Roaming\go\env
set GOEXE=.exe
set GOEXPERIMENT=
set GOFIPS140=off
set GOFLAGS=
set GOGCCFLAGS=-m64 -mthreads -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=C:\Users\jabaile\AppData\Local\Temp\go-build3919903901=/tmp/go-build -gno-record-gcc-switches
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMOD=D:\work\TypeScript-go\go.mod
set GOMODCACHE=C:\Users\jabaile\go\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\jabaile\go
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=C:\Users\jabaile\scoop\apps\go\current
set GOSUMDB=sum.golang.org
set GOTELEMETRY=local
set GOTELEMETRYDIR=C:\Users\jabaile\AppData\Roaming\go\telemetry
set GOTMPDIR=
set GOTOOLCHAIN=auto
set GOTOOLDIR=C:\Users\jabaile\scoop\apps\go\current\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.24.1
set GOWORK=
set PKG_CONFIG=pkg-config

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).

$ git clone --recurse-submodules https://github.com/microsoft/typescript-go.git
$ cd typescript-go
# warm the caches
$ go test ./internal/testrunner
# clean the test cache only
$ go clean -testcache
$ Measure-Command { go test ./internal/testrunner | Out-Default }
$ Measure-Command { go test -count=1 ./internal/testrunner | Out-Default }

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:

$ Measure-Command { go test ./internal/testrunner | Out-Default }
ok      github.com/microsoft/typescript-go/internal/testrunner  13.584s

Days              : 0
Hours             : 0
Minutes           : 1
Seconds           : 5
Milliseconds      : 364
Ticks             : 653649277
TotalDays         : 0.000756538515046296
TotalHours        : 0.0181569243611111
TotalMinutes      : 1.08941546166667
TotalSeconds      : 65.3649277
TotalMilliseconds : 65364.9277

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:

$ Measure-Command { go test -count=1 ./internal/testrunner | Out-Default }
ok      github.com/microsoft/typescript-go/internal/testrunner  11.726s

Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 15
Milliseconds      : 296
Ticks             : 152960956
TotalDays         : 0.000177038143518519
TotalHours        : 0.00424891544444444
TotalMinutes      : 0.254934926666667
TotalSeconds      : 15.2960956
TotalMilliseconds : 15296.0956

This doesn't reproduce on Linux.

[seankhliao]

maybe #35801

[gabyhelp]

Related Issues

• cmd/test: caching test results takes 50 seconds #35801 (closed)
• cmd/go clean -testcache does not clean test cache #29757 (closed)
• cmd/go: don't cache tests that use testing/quick.Check and friends #26276 (closed)
• cmd/go: cache tests with -race flag #61608 (closed)
• cmd/go: cache hit takes too long on a test that opens many files #26726
• cmd/go: test cached run slower than real test run #26562
• cmd/go: go test cached test times have increased 6x since Go 1.10 #26157 (closed)
• cmd/go: long tests failing on Windows #25300 (closed)
• cmd/go: `go test` takes extra time to run even for packages that do not have any test files #17248 (closed)
• cmd/go: test reported as cached, but not actually cached #41593

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[jakebailey]

#26562, #61608 above are related too, but unlike the past closed issues I actually have a repro 😄

[prattmic]

cc @matloob @samthanawalla

[prattmic]

Odd, I can't clone the repo at all on Windows:

$ git clone --recurse-submodules https://github.com/microsoft/typescript-go.git
Cloning into 'typescript-go'...                  
remote: Enumerating objects: 95648, done.        
remote: Counting objects: 100% (11177/11177), done.
remote: Compressing objects: 100% (7548/7548), done.
remote: Total 95648 (delta 4558), reused 3646 (delta 3625), pack-reused 84471 (from 3)
Receiving objects: 100% (95648/95648), 60.42 MiB | 19.73 MiB/s, done.
Resolving deltas: 100% (26407/26407), done.      
Updating files: 100% (65383/65383), done.                               
Submodule '_submodules/TypeScript' (https://github.com/microsoft/TypeScript.git) registered for path '_submodules/TypeScript'
Cloning into 'C:/b/s/w/ir/typescript-go/_submodules/TypeScript'...                               
remote: Enumerating objects: 737700, done.                                                       
remote: Counting objects: 100% (107/107), done.                  
remote: Compressing objects: 100% (65/65), done.         
remote: Total 737700 (delta 68), reused 50 (delta 41), pack-reused 737593 (from 2)        
Receiving objects: 100% (737700/737700), 2.73 GiB | 36.99 MiB/s, done.
Resolving deltas: 100% (513580/513580), done.                                                                                                                                                    
error: unable to create file tests/baselines/reference/tsserver/configuredProjects/Open-ref-of-configured-project-when-open-file-gets-added-to-the-project-as-part-of-configured-file-update-buts
-its-open-file-references-are-all-closed-when-the-update-happens.js: Filename too long           
error: unable to create file tests/baselines/reference/tsserver/projectReferences/solution-with-its-own-files-and-disables-looking-into-the-child-project-if-disableReferencedProjectLoad-is-set-
in-first-indirect-project-but-not-in-another-one.js: Filename too long                           
fatal: Unable to checkout '52c59dbcbee274e523ef39e6c8be1bd5e110c2f1' in submodule path '_submodules/TypeScript'

[jakebailey]

Your git install may not have long paths enabled; the Windows GUI installer I think preselects the option but some installs might not.

git config --global core.longpaths true

(Apologies for the terribly long test names; they're autogenerated and used to "fit" before we started using the repo as a submodule...)

[prattmic]

Thanks, I'll give that a try.

FWIW, I can reproduce this on Linux, but the delta is less extreme at ~2x:

$ go clean -testcache
$ /usr/bin/time -p go test ./internal/testrunner
ok      github.com/microsoft/typescript-go/internal/testrunner  10.641s
real 24.05
user 58.48
sys 13.87
$ /usr/bin/time -p go test -count=1 ./internal/testrunner
ok      github.com/microsoft/typescript-go/internal/testrunner  10.672s
real 11.93
user 51.42
sys 8.00

24s vs 12s

[jakebailey]

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 total

Not quite as pronounced on my machine but I guess I couldn't tell 9 seconds from 14 seconds.

[prattmic]

I managed to reproduce on a gotip-windows-amd64 gomote by setting git config --global core.longpaths true first.

There I get 110s vs 16s.

[prattmic]

Back to Linux, looking at system calls via strace.

Here are the syscall counts with -count=1:

 492462 fcntl
 309607 newfstatat
 249177 read
 218362 openat
 129989 nanosleep
 123908 close
 120450 fstat
  57962 futex
  21703 getpid
  21681 tgkill
   4089 lseek
   2943 mmap
   1479 getdents64
   1273 write
    335 unlinkat
    252 sigaltstack
    217 gettid
    209 pread64
    161 mkdirat
    115 clone
     87 madvise
     63 dup3
     59 pipe2
     50 mprotect
     28 execve
     24 prlimit64
     24 munmap
     23 waitid
     21 eventfd2
     18 flock
     15 rseq
     12 clone3
     11 brk
      9 readlink
      6 access
      4 ftruncate
      4 faccessat2
      3 readlinkat
      2 utimensat
      2 ioctl
      2 getrandom
      2 fallocate
      2 chdir
      1 wait4
      1 uname
      1 pwrite64

And with caching:

2809756 newfstatat
 507101 nanosleep
 492518 fcntl
 372379 futex
 250883 read
 219527 openat
 125071 close
 120453 fstat
  18013 getpid
  17991 tgkill
  16043 write
   4089 lseek
   3930 getdents64
   2896 mmap
   1340 madvise
    336 unlinkat
    250 sigaltstack
    216 gettid
    209 pread64
    160 mkdirat
    115 clone
     64 dup3
     59 pipe2
     48 mprotect
     28 execve
     24 waitid
     24 prlimit64
     24 munmap
     21 eventfd2
     18 flock
     14 rseq
     11 clone3
     11 brk
      9 readlink
      8 utimensat
      8 ftruncate
      6 access
      4 faccessat2
      3 readlinkat
      2 ioctl
      2 getrandom
      2 fallocate
      2 chdir
      1 wait4
      1 uname
      1 pwrite64

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.