search

golang / go

The Go programming language
https://go.dev
BSD 3-Clause "New" or "Revised" License
124.38k stars 17.71k forks source link

cmd/go: go test cached test times have increased 6x since Go 1.10 #26157

Closed davecheney closed 6 years ago

davecheney commented 6 years ago

Please answer these questions before submitting your issue. Thanks!

What version of Go are you using (go version)?

go version devel +da769814b8 Fri Jun 29 23:22:48 2018 +0000 darwin/amd64

Does this issue reproduce with the latest release?

No, this is a regression from Go 1.10.3

What operating system and processor architecture are you using (go env)?

darwin/amd64

What did you do?

I recently updated to the latest master branch, I hadn't updated for a month or so, and found that go test times for a project with mostly cached tests have increased from less than a second to near 6 seconds.

Daves-MacBook-Pro(~/src/github.com/heptio/contour) % time go1.10 test ./...
?       github.com/heptio/contour/apis/contour/v1beta1  [no test files]
?       github.com/heptio/contour/cmd/contour   [no test files]
ok      github.com/heptio/contour/internal/contour      (cached)
ok      github.com/heptio/contour/internal/dag  (cached)
?       github.com/heptio/contour/internal/debug        [no test files]
ok      github.com/heptio/contour/internal/e2e  (cached)
ok      github.com/heptio/contour/internal/envoy        (cached)
?       github.com/heptio/contour/internal/generated/clientset/versioned        [no test files]
?       github.com/heptio/contour/internal/generated/clientset/versioned/fake   [no test files]
?       github.com/heptio/contour/internal/generated/clientset/versioned/scheme [no test files]
?       github.com/heptio/contour/internal/generated/clientset/versioned/typed/contour/v1beta1  [no test files]                                                                                                
?       github.com/heptio/contour/internal/generated/clientset/versioned/typed/contour/v1beta1/fake    [no test files]                                                                                         
?       github.com/heptio/contour/internal/generated/informers/externalversions [no test files]
?       github.com/heptio/contour/internal/generated/informers/externalversions/contour [no test files]
?       github.com/heptio/contour/internal/generated/informers/externalversions/contour/v1beta1 [no test files]                                                                                                
?       github.com/heptio/contour/internal/generated/informers/externalversions/internalinterfaces     [no test files]                                                                                         
?       github.com/heptio/contour/internal/generated/listers/contour/v1beta1    [no test files]
ok      github.com/heptio/contour/internal/grpc (cached)
?       github.com/heptio/contour/internal/k8s  [no test files]
ok      github.com/heptio/contour/internal/listener     (cached)
ok      github.com/heptio/contour/internal/route        (cached)

real    0m0.936s
user    0m2.864s
sys     0m0.915s
Daves-MacBook-Pro(~/src/github.com/heptio/contour) % time go test ./...
?       github.com/heptio/contour/apis/contour/v1beta1  0.017s [no test files]
?       github.com/heptio/contour/cmd/contour   0.058s [no test files]
ok      github.com/heptio/contour/internal/contour      (cached)
ok      github.com/heptio/contour/internal/dag  (cached)
?       github.com/heptio/contour/internal/debug        0.027s [no test files]
ok      github.com/heptio/contour/internal/e2e  (cached)
ok      github.com/heptio/contour/internal/envoy        (cached)
?       github.com/heptio/contour/internal/generated/clientset/versioned        0.027s [no test files]
?       github.com/heptio/contour/internal/generated/clientset/versioned/fake   0.034s [no test files]
?       github.com/heptio/contour/internal/generated/clientset/versioned/scheme 0.019s [no test files]
?       github.com/heptio/contour/internal/generated/clientset/versioned/typed/contour/v1beta1  0.058s [no test files]                                                                                         
?       github.com/heptio/contour/internal/generated/clientset/versioned/typed/contour/v1beta1/fake    0.029s [no test files]                                                                                  
?       github.com/heptio/contour/internal/generated/informers/externalversions 0.041s [no test files]
?       github.com/heptio/contour/internal/generated/informers/externalversions/contour 0.025s [no test files]                                                                                                 
?       github.com/heptio/contour/internal/generated/informers/externalversions/contour/v1beta1 0.025s [no test files]                                                                                         
?       github.com/heptio/contour/internal/generated/informers/externalversions/internalinterfaces     0.029s [no test files]                                                                                  
?       github.com/heptio/contour/internal/generated/listers/contour/v1beta1    0.017s [no test files]
ok      github.com/heptio/contour/internal/grpc (cached)
?       github.com/heptio/contour/internal/k8s  0.018s [no test files]
ok      github.com/heptio/contour/internal/listener     (cached)
ok      github.com/heptio/contour/internal/route        (cached)

real    0m5.751s
user    0m27.815s
sys     0m6.072s

What did you expect to see?

time go1.10 test ./... and time go test ./... should be equivalent

What did you see instead?

Time to run cached tests under Go 1.10

real    0m0.936s
user    0m2.864s
sys     0m0.915s

Time to run cached tests under Go tip

real    0m5.751s
user    0m27.815s
sys     0m6.072s
davecheney commented 6 years ago

The regression occurred after 161874da2ab6d5372043a1f3938a81a19d1165ad

Daves-MacBook-Pro(~/src/github.com/heptio/contour) % time go test ./...
?       github.com/heptio/contour/apis/contour/v1beta1  [no test files]
?       github.com/heptio/contour/cmd/contour   [no test files]
ok      github.com/heptio/contour/internal/contour      (cached)
ok      github.com/heptio/contour/internal/dag  (cached)
?       github.com/heptio/contour/internal/debug        [no test files]
ok      github.com/heptio/contour/internal/e2e  (cached)
ok      github.com/heptio/contour/internal/envoy        (cached)
?       github.com/heptio/contour/internal/generated/clientset/versioned        [no test files]
?       github.com/heptio/contour/internal/generated/clientset/versioned/fake   [no test files]
?       github.com/heptio/contour/internal/generated/clientset/versioned/scheme [no test files]
?       github.com/heptio/contour/internal/generated/clientset/versioned/typed/contour/v1beta1  [no test files]                                                                                                
?       github.com/heptio/contour/internal/generated/clientset/versioned/typed/contour/v1beta1/fake    [no test files]                                                                                         
?       github.com/heptio/contour/internal/generated/informers/externalversions [no test files]
?       github.com/heptio/contour/internal/generated/informers/externalversions/contour [no test files]
?       github.com/heptio/contour/internal/generated/informers/externalversions/contour/v1beta1 [no test files]                                                                                                
?       github.com/heptio/contour/internal/generated/informers/externalversions/internalinterfaces     [no test files]                                                                                         
?       github.com/heptio/contour/internal/generated/listers/contour/v1beta1    [no test files]
ok      github.com/heptio/contour/internal/grpc (cached)
?       github.com/heptio/contour/internal/k8s  [no test files]
ok      github.com/heptio/contour/internal/listener     (cached)
ok      github.com/heptio/contour/internal/route        (cached)

real    0m0.861s
user    0m2.478s
sys     0m0.965s
Daves-MacBook-Pro(~/src/github.com/heptio/contour) % go version
go version devel +161874da2a Fri Jun 1 21:52:00 2018 +0000 darwin/amd64
davecheney commented 6 years ago

git bisect suggests that ebb8a1f8e6bf14ce4773e930870985571aaff932 is potentially the cause.

andybons commented 6 years ago

@ianlancetaylor

andybons commented 6 years ago

@bcmills @Kyroy

ianlancetaylor commented 6 years ago

That change (https://golang.org/cl/115095) will definitely increase the time required for running tests for a package that has no tests. cmd/go will now build and run the test binary, when it didn't before.

The question is: do we care?

bcmills commented 6 years ago

Even if it takes time to build and run the test binary, the result of building and running that binary should be cached; from the second set of timings, it appears that that is no longer the case.

ianlancetaylor commented 6 years ago

We cache compiler outputs, but as far as I know we don't cache linker outputs. When I run go test -test.count=1 bytes I see that it relinks bytes.test, even if it has been previously linked

davecheney commented 6 years ago

-count=n disables caching afaik

On 3 Jul 2018, at 06:33, Ian Lance Taylor notifications@github.com wrote:

We cache compiler outputs, but as far as I know we don't cache linker outputs. When I run go test -test.count=1 bytes I see that it relinks bytes.test, even if it has been previously linked

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub, or mute the thread.

ianlancetaylor commented 6 years ago

-count=n disables the caching of the running of the test binary. It doesn't disable the caching of the building of the test binary.

davecheney commented 6 years ago

What is the logic behind building a test binary then not running it?

On 3 July 2018 at 10:23, Ian Lance Taylor notifications@github.com wrote:

-count=n disables the caching of the running of the test binary. It doesn't disable the caching of the building of the test binary.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/golang/go/issues/26157#issuecomment-401976029, or mute the thread https://github.com/notifications/unsubscribe-auth/AAAcAyDRhtNl4djvzOQRP05GmydW3rJjks5uCrmagaJpZM4U99bT .

ianlancetaylor commented 6 years ago

What is the logic behind building a test binary then not running it?

It's certainly possible that the inputs have changed in a way that doesn't change the test binary, in which case that is exactly what will happen.

Still, you're right, it would be nice if we could skip building the test binary if the hash of the inputs points us to a cached test result. And maybe it is already supposed to work that way, I'm not sure. So I guess I was wrong in my comment above: there is something to do here.

rsc commented 6 years ago

Duplicate (now) of #26242, which we will fix for Go 1.11. (To reply to Ian's comment, yes the implementation goes out of its way to avoid the compile + link if there's an up-to-date cached test result.)

gopherbot commented 6 years ago

Change https://golang.org/cl/122518 mentions this issue: cmd/go: revert "output coverage report even if there are no test files"

davecheney commented 6 years ago

Thanks Russ!

On 7 Jul 2018, at 03:32, Russ Cox notifications@github.com wrote:

Duplicate (now) of #26242, which we will fix for Go 1.11. (To reply to Ian's comment, yes the implementation goes out of its way to avoid the compile + link if there's an up-to-date cached test result.)

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub, or mute the thread.