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.

Sign up for GitHub

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

Jump to bottom

x/tools/go/analysis/analysistest: -race flag slows down tests significantly #62283

Closed
Antonboom opened this issue Aug 25, 2023 · 2 comments
Closed

x/tools/go/analysis/analysistest: -race flag slows down tests significantly #62283

Antonboom opened this issue Aug 25, 2023 · 2 comments
Labels
Performance pkgsite RaceDetector Tools This label describes issues relating to any tools in the x/tools repository.
Milestone
Unreleased

Comments

@Antonboom
Copy link

Hello, team!

Problem statement

On my linter I was noticed that after turning on "race detection" my tests (based on analysistest.RunWithSuggestedFixes) started to last instead of 10 seconds on average 50:

$ go test -count 1 ./...                                    
ok      github.com/xxx/analyzer       13.136s

$ go test -count 1 -race ./...                                    
ok      github.com/xxx/analyzer       69.423s

Linter code does not use goroutines and synchronization mechanisms – just typical AST analysis.
But we have ~10 testdata packages with generated test and golden files pairs (avg 200 lines per file).
analysistest.Run runs separatly per package (with t.Parallel()).

I tried to repeat it on go/analysis checkers:

$ go version                                                      
go version go1.21.0 darwin/arm64

$ cd $GOPATH/pkg/mod/golang.org/x/tools@v0.12.0/go/analysis/passes                                                                                                                                                                                    

$ go test -count=1 ./... | grep ok | sort -k2
ok      golang.org/x/tools/go/analysis/passes/asmdecl                 2.234s
ok      golang.org/x/tools/go/analysis/passes/assign                  1.797s
ok      golang.org/x/tools/go/analysis/passes/atomic                  2.358s
ok      golang.org/x/tools/go/analysis/passes/atomicalign             1.721s
ok      golang.org/x/tools/go/analysis/passes/bools                   2.370s
ok      golang.org/x/tools/go/analysis/passes/buildssa                2.643s
ok      golang.org/x/tools/go/analysis/passes/buildtag                2.781s
ok      golang.org/x/tools/go/analysis/passes/cgocall                 3.736s
ok      golang.org/x/tools/go/analysis/passes/composite               3.230s
ok      golang.org/x/tools/go/analysis/passes/copylock                2.717s
ok      golang.org/x/tools/go/analysis/passes/ctrlflow                3.548s
ok      golang.org/x/tools/go/analysis/passes/deepequalerrors         3.181s
ok      golang.org/x/tools/go/analysis/passes/defers                  3.152s
ok      golang.org/x/tools/go/analysis/passes/directive               3.138s
ok      golang.org/x/tools/go/analysis/passes/errorsas                2.675s
ok      golang.org/x/tools/go/analysis/passes/fieldalignment          0.463s
ok      golang.org/x/tools/go/analysis/passes/findcall                0.755s
ok      golang.org/x/tools/go/analysis/passes/framepointer            0.351s
ok      golang.org/x/tools/go/analysis/passes/httpresponse            2.885s
ok      golang.org/x/tools/go/analysis/passes/ifaceassert             1.120s
ok      golang.org/x/tools/go/analysis/passes/internal/analysisutil   0.748s
ok      golang.org/x/tools/go/analysis/passes/loopclosure             2.601s
ok      golang.org/x/tools/go/analysis/passes/lostcancel              2.566s
ok      golang.org/x/tools/go/analysis/passes/nilfunc                 1.072s
ok      golang.org/x/tools/go/analysis/passes/nilness                 0.938s
ok      golang.org/x/tools/go/analysis/passes/pkgfact                 0.766s
ok      golang.org/x/tools/go/analysis/passes/printf                  1.875s
ok      golang.org/x/tools/go/analysis/passes/reflectvaluecompare     1.604s
ok      golang.org/x/tools/go/analysis/passes/shadow                  1.744s
ok      golang.org/x/tools/go/analysis/passes/shift                   0.450s
ok      golang.org/x/tools/go/analysis/passes/sigchanyzer             1.343s
ok      golang.org/x/tools/go/analysis/passes/slog                    1.769s
ok      golang.org/x/tools/go/analysis/passes/sortslice               1.426s
ok      golang.org/x/tools/go/analysis/passes/stdmethods              3.849s
ok      golang.org/x/tools/go/analysis/passes/stringintconv           0.803s
ok      golang.org/x/tools/go/analysis/passes/structtag               1.926s
ok      golang.org/x/tools/go/analysis/passes/testinggoroutine        2.082s
ok      golang.org/x/tools/go/analysis/passes/tests                   2.700s
ok      golang.org/x/tools/go/analysis/passes/timeformat              2.025s
ok      golang.org/x/tools/go/analysis/passes/unmarshal               1.951s
ok      golang.org/x/tools/go/analysis/passes/unreachable             0.367s
ok      golang.org/x/tools/go/analysis/passes/unsafeptr               1.343s
ok      golang.org/x/tools/go/analysis/passes/unusedresult            0.950s
ok      golang.org/x/tools/go/analysis/passes/unusedwrite             0.338s
ok      golang.org/x/tools/go/analysis/passes/usesgenerics            0.304s

$ go test -race -count=1 ./... | grep ok | sort -k2
ok      golang.org/x/tools/go/analysis/passes/asmdecl               2.796s
ok      golang.org/x/tools/go/analysis/passes/assign                3.298s
ok      golang.org/x/tools/go/analysis/passes/atomic                2.005s
ok      golang.org/x/tools/go/analysis/passes/atomicalign           2.538s
ok      golang.org/x/tools/go/analysis/passes/bools                 4.293s
ok      golang.org/x/tools/go/analysis/passes/buildssa              2.843s
ok      golang.org/x/tools/go/analysis/passes/buildtag              2.947s
ok      golang.org/x/tools/go/analysis/passes/cgocall               9.715s
ok      golang.org/x/tools/go/analysis/passes/composite             8.916s
ok      golang.org/x/tools/go/analysis/passes/copylock              5.843s
ok      golang.org/x/tools/go/analysis/passes/ctrlflow              8.437s
ok      golang.org/x/tools/go/analysis/passes/deepequalerrors       7.182s
ok      golang.org/x/tools/go/analysis/passes/defers                7.642s
ok      golang.org/x/tools/go/analysis/passes/directive             7.164s
ok      golang.org/x/tools/go/analysis/passes/errorsas              4.948s
ok      golang.org/x/tools/go/analysis/passes/fieldalignment        1.415s
ok      golang.org/x/tools/go/analysis/passes/findcall              1.643s
ok      golang.org/x/tools/go/analysis/passes/framepointer          1.374s
ok      golang.org/x/tools/go/analysis/passes/httpresponse          2.461s
ok      golang.org/x/tools/go/analysis/passes/ifaceassert           4.517s
ok      golang.org/x/tools/go/analysis/passes/internal/analysisutil 1.312s
ok      golang.org/x/tools/go/analysis/passes/loopclosure           7.186s
ok      golang.org/x/tools/go/analysis/passes/lostcancel            7.197s
ok      golang.org/x/tools/go/analysis/passes/nilfunc               1.603s
ok      golang.org/x/tools/go/analysis/passes/nilness               1.947s
ok      golang.org/x/tools/go/analysis/passes/pkgfact               1.363s
ok      golang.org/x/tools/go/analysis/passes/printf                9.001s
ok      golang.org/x/tools/go/analysis/passes/reflectvaluecompare   7.172s
ok      golang.org/x/tools/go/analysis/passes/shadow                6.381s
ok      golang.org/x/tools/go/analysis/passes/shift                 1.426s
ok      golang.org/x/tools/go/analysis/passes/sigchanyzer           6.243s
ok      golang.org/x/tools/go/analysis/passes/slog                  6.673s
ok      golang.org/x/tools/go/analysis/passes/sortslice             4.641s
ok      golang.org/x/tools/go/analysis/passes/stdmethods            2.648s
ok      golang.org/x/tools/go/analysis/passes/stringintconv         1.392s
ok      golang.org/x/tools/go/analysis/passes/structtag             8.706s
ok      golang.org/x/tools/go/analysis/passes/testinggoroutine      8.540s
ok      golang.org/x/tools/go/analysis/passes/tests                 8.992s
ok      golang.org/x/tools/go/analysis/passes/timeformat            6.242s
ok      golang.org/x/tools/go/analysis/passes/unmarshal             7.900s
ok      golang.org/x/tools/go/analysis/passes/unreachable           1.627s
ok      golang.org/x/tools/go/analysis/passes/unsafeptr             6.500s
ok      golang.org/x/tools/go/analysis/passes/unusedresult          5.498s
ok      golang.org/x/tools/go/analysis/passes/unusedwrite           1.427s
ok      golang.org/x/tools/go/analysis/passes/usesgenerics          1.381s

Calculate rate:

$ python3 calc.py
golang.org/x/tools/go/analysis/passes/asmdecl               	2.796/2.234 = 1.252
golang.org/x/tools/go/analysis/passes/assign                	3.298/1.797 = 1.835
golang.org/x/tools/go/analysis/passes/atomic                	2.005/2.358 = 0.850
golang.org/x/tools/go/analysis/passes/atomicalign           	2.538/1.721 = 1.475
golang.org/x/tools/go/analysis/passes/bools                 	4.293/2.370 = 1.811
golang.org/x/tools/go/analysis/passes/buildssa              	2.843/2.643 = 1.076
golang.org/x/tools/go/analysis/passes/buildtag              	2.947/2.781 = 1.060
golang.org/x/tools/go/analysis/passes/cgocall               	9.715/3.736 = 2.600
golang.org/x/tools/go/analysis/passes/composite             	8.916/3.230 = 2.760
golang.org/x/tools/go/analysis/passes/copylock              	5.843/2.717 = 2.151
golang.org/x/tools/go/analysis/passes/ctrlflow              	8.437/3.548 = 2.378
golang.org/x/tools/go/analysis/passes/deepequalerrors       	7.182/3.181 = 2.258
golang.org/x/tools/go/analysis/passes/defers                	7.642/3.152 = 2.424
golang.org/x/tools/go/analysis/passes/directive             	7.164/3.138 = 2.283
golang.org/x/tools/go/analysis/passes/errorsas              	4.948/2.675 = 1.850
golang.org/x/tools/go/analysis/passes/fieldalignment        	1.415/0.463 = 3.056
golang.org/x/tools/go/analysis/passes/findcall              	1.643/0.755 = 2.176
golang.org/x/tools/go/analysis/passes/framepointer          	1.374/0.351 = 3.915
golang.org/x/tools/go/analysis/passes/httpresponse          	2.461/2.885 = 0.853
golang.org/x/tools/go/analysis/passes/ifaceassert           	4.517/1.120 = 4.033
golang.org/x/tools/go/analysis/passes/internal/analysisutil 	1.312/0.748 = 1.754
golang.org/x/tools/go/analysis/passes/loopclosure           	7.186/2.601 = 2.763
golang.org/x/tools/go/analysis/passes/lostcancel            	7.197/2.566 = 2.805
golang.org/x/tools/go/analysis/passes/nilfunc               	1.603/1.072 = 1.495
golang.org/x/tools/go/analysis/passes/nilness               	1.947/0.938 = 2.076
golang.org/x/tools/go/analysis/passes/pkgfact               	1.363/0.766 = 1.779
golang.org/x/tools/go/analysis/passes/printf                	9.001/1.875 = 4.801
golang.org/x/tools/go/analysis/passes/reflectvaluecompare   	7.172/1.604 = 4.471
golang.org/x/tools/go/analysis/passes/shadow                	6.381/1.744 = 3.659
golang.org/x/tools/go/analysis/passes/shift                 	1.426/0.450 = 3.169
golang.org/x/tools/go/analysis/passes/sigchanyzer           	6.243/1.343 = 4.649
golang.org/x/tools/go/analysis/passes/slog                  	6.673/1.769 = 3.772
golang.org/x/tools/go/analysis/passes/sortslice             	4.641/1.426 = 3.255
golang.org/x/tools/go/analysis/passes/stdmethods            	2.648/3.849 = 0.688
golang.org/x/tools/go/analysis/passes/stringintconv         	1.392/0.803 = 1.733
golang.org/x/tools/go/analysis/passes/structtag             	8.706/1.926 = 4.520
golang.org/x/tools/go/analysis/passes/testinggoroutine      	8.540/2.082 = 4.102
golang.org/x/tools/go/analysis/passes/tests                 	8.992/2.700 = 3.330
golang.org/x/tools/go/analysis/passes/timeformat            	6.242/2.025 = 3.082
golang.org/x/tools/go/analysis/passes/unmarshal             	7.900/1.951 = 4.049
golang.org/x/tools/go/analysis/passes/unreachable           	1.627/0.367 = 4.433
golang.org/x/tools/go/analysis/passes/unsafeptr             	6.500/1.343 = 4.840
golang.org/x/tools/go/analysis/passes/unusedresult          	5.498/0.950 = 5.787
golang.org/x/tools/go/analysis/passes/unusedwrite           	1.427/0.338 = 4.222
golang.org/x/tools/go/analysis/passes/usesgenerics          	1.381/0.304 = 4.543

AVG: 2.842

Get top:

$ python3 calc.py | sort -r -k4 | head -n 5
golang.org/x/tools/go/analysis/passes/unusedresult          	5.498/0.950 = 5.787
golang.org/x/tools/go/analysis/passes/unsafeptr             	6.500/1.343 = 4.840
golang.org/x/tools/go/analysis/passes/printf                	9.001/1.875 = 4.801
golang.org/x/tools/go/analysis/passes/sigchanyzer           	6.243/1.343 = 4.649
golang.org/x/tools/go/analysis/passes/usesgenerics          	1.381/0.304 = 4.543

Question

Such slowing - is it expected behavior or not?

P.S. I apologize for the superficial (evaluative) tests instead of point profiling. Thanks.
@gopherbot gopherbot added the Tools This label describes issues relating to any tools in the x/tools repository. label Aug 25, 2023
@gopherbot gopherbot added this to the Unreleased milestone Aug 25, 2023
@bcmills
Copy link
Contributor

bcmills commented Aug 25, 2023

This is expected — it is within the bounds described in https://go.dev/doc/articles/race_detector#Runtime_Overheads.

@bcmills bcmills closed this as not planned Won't fix, can't repro, duplicate, stale Aug 25, 2023
@Antonboom
Copy link
Author

Antonboom commented Aug 25, 2023 •
edited

Yes, I'm aware about this, but never experienced before such a significant slowdown.
Thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Performance pkgsite RaceDetector Tools This label describes issues relating to any tools in the x/tools repository.
Projects
None yet
Milestone
Unreleased
Development

No branches or pull requests
3 participants
@bcmills @gopherbot @Antonboom