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: go test cached test times have increased 6x since Go 1.10 #26157

Closed
davecheney opened this issue Jun 30, 2018 · 14 comments
Closed

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

davecheney opened this issue Jun 30, 2018 · 14 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. release-blocker
Milestone

Comments

@davecheney
Copy link
Contributor

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
Copy link
Contributor Author

The regression occurred after 161874d

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
Copy link
Contributor Author

git bisect suggests that ebb8a1f is potentially the cause.

@davecheney davecheney added this to the Go1.11 milestone Jun 30, 2018
@andybons
Copy link
Member

andybons commented Jul 2, 2018

@ianlancetaylor

@andybons andybons added release-blocker NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Jul 2, 2018
@andybons
Copy link
Member

andybons commented Jul 2, 2018

@bcmills @kyroy

@ianlancetaylor
Copy link
Contributor

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
Copy link
Contributor

bcmills commented Jul 2, 2018

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
Copy link
Contributor

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
Copy link
Contributor Author

davecheney commented Jul 2, 2018 via email

@ianlancetaylor
Copy link
Contributor

-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
Copy link
Contributor Author

davecheney commented Jul 3, 2018 via email

@ianlancetaylor
Copy link
Contributor

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
Copy link
Contributor

rsc commented Jul 6, 2018

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

@rsc rsc closed this as completed Jul 6, 2018
@gopherbot
Copy link

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

@davecheney
Copy link
Contributor Author

davecheney commented Jul 6, 2018 via email

gopherbot pushed a commit that referenced this issue Jul 9, 2018
Original CL description:

    When using test -cover or -coverprofile the output for "no test files"
    is the same format as for "no tests to run".

Reverting because this CL changed cmd/go to build test binaries for
packages that have no tests, leading to extra work and confusion.

Updates #24570
Fixes #25789
Fixes #26157
Fixes #26242

Change-Id: Ibab1307d39dfaec0de9359d6d96706e3910c8efd
Reviewed-on: https://go-review.googlesource.com/122518
Run-TryBot: Ian Lance Taylor <iant@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Russ Cox <rsc@golang.org>
@golang golang locked and limited conversation to collaborators Jul 6, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. release-blocker
Projects
None yet
Development

No branches or pull requests

6 participants