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

Comments

Projects
None yet
6 participants
@davecheney
Copy link
Contributor

commented Jun 30, 2018

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

This comment has been minimized.

Copy link
Contributor Author

commented Jun 30, 2018

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

This comment has been minimized.

Copy link
Contributor Author

commented Jun 30, 2018

git bisect suggests that ebb8a1f is potentially the cause.

@davecheney davecheney added this to the Go1.11 milestone Jun 30, 2018

@andybons

This comment has been minimized.

Copy link
Member

commented Jul 2, 2018

@andybons

This comment has been minimized.

Copy link
Member

commented Jul 2, 2018

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

commented Jul 2, 2018

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

This comment has been minimized.

Copy link
Member

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

This comment has been minimized.

Copy link
Contributor

commented Jul 2, 2018

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

This comment has been minimized.

Copy link
Contributor Author

commented Jul 2, 2018

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

commented Jul 3, 2018

-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

This comment has been minimized.

Copy link
Contributor Author

commented Jul 3, 2018

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

commented Jul 3, 2018

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

This comment has been minimized.

Copy link
Contributor

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 Jul 6, 2018

@gopherbot

This comment has been minimized.

Copy link

commented Jul 6, 2018

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

@davecheney

This comment has been minimized.

Copy link
Contributor Author

commented Jul 6, 2018

gopherbot pushed a commit that referenced this issue Jul 9, 2018

cmd/go: revert "output coverage report even if there are no test files"
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>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.