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

x/tools/cmd/goimports: painfully slow when cold #20610

Closed
dominicbarnes opened this issue Jun 8, 2017 · 8 comments
Closed

x/tools/cmd/goimports: painfully slow when cold #20610

dominicbarnes opened this issue Jun 8, 2017 · 8 comments
Labels
FrozenDueToAge help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Performance Tools This label describes issues relating to any tools in the x/tools repository.
Milestone

Comments

@dominicbarnes
Copy link

Please answer these questions before submitting your issue. Thanks!

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

$ go version
go version go1.8.1 linux/amd64

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

$ go env
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/dominic/dev"
GORACE=""
GOROOT="/usr/lib/go-1.8"
GOTOOLDIR="/usr/lib/go-1.8/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build184946284=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

What did you do?

The very first time I run goimports (ie: "cold") on a file that has any third-party imports, it is painfully slow. (30-60s in most cases) The complexity of the file (ie: LOC and number of imports) seems to matter very little, if at all.

After that initial run, it is blazing fast (<300ms) for every subsequent file.

What did you expect to see?

I don't get the impression that goimports runs slowly as a general rule, so I expect it to be much faster than what I get.

What did you see instead?

That initial run is painful, especially because I use a text editor that runs goimports automatically on save. I end up needing to trigger some trivial goimports manually in a terminal in order for my text editor to not freeze up on each save.

I have a lot of repos in my $GOPATH, but before I start blowing packages away I would like to see if there's something else I may have misconfigured or could try to address this.

I only have this trouble on my linux desktop. I also develop on a mac laptop, but never have trouble with goimports there. (and I believe the size of $GOPATH is comparable since I use both for work) It seems to be a linux-exclusive issue for me.

@cznic
Copy link
Contributor

cznic commented Jun 8, 2017

I don't use goimports, but I use godoc -http:6060 and when it starts it solves the same problem. It also used to start responding only after minutes. Once I installed a SSD disk instead of the old mechanical one, it slurps the same $GOPATH content in just a few seconds. Maybe you're in the same situation (?).

@bradfitz
Copy link
Contributor

bradfitz commented Jun 8, 2017

When cold, what does goimports -v some_incomplete_file.go say?

How large are your $GOPATH(s) by file count and bytes?

SSD or not? What type of filesystem?

If you have lots of stuff in your GOPATH and a slow disk or filesystem, adding to the .goimportsignore can help. See https://godoc.org/golang.org/x/tools/cmd/goimports for the details of that.

@bradfitz bradfitz changed the title goimports painfully slow when cold x/tools/cmd/goimports: painfully slow when cold Jun 8, 2017
@gopherbot gopherbot added this to the Unreleased milestone Jun 8, 2017
@dominicbarnes
Copy link
Author

@bradfitz here's the output when I run in verbose more:

2017/06/10 08:30:51.843595 fixImports(filename="functions/migrate/params.go"), abs="/home/dominic/dev/src/github.com/segmentio/lambda-warehouses/functions/migrate/params.go", srcDir="/home/dominic/dev/src/github.com/segmentio/lambda-warehouses/functions/migrate" ...
2017/06/10 08:30:51.844684 importPathToNameGoPathParse("github.com/aws/aws-sdk-go/service/rds", srcDir="/home/dominic/dev/src/github.com/segmentio/lambda-warehouses/functions/migrate") = "rds", <nil>
2017/06/10 08:30:51.844845 importPathToNameGoPathParse("github.com/aws/aws-sdk-go/service/rds/rdsiface", srcDir="/home/dominic/dev/src/github.com/segmentio/lambda-warehouses/functions/migrate") = "rdsiface", <nil>
2017/06/10 08:30:51.844954 importPathToNameGoPathParse("github.com/segmentio/kit/log", srcDir="/home/dominic/dev/src/github.com/segmentio/lambda-warehouses/functions/migrate") = "log", <nil>
2017/06/10 08:30:51.845532 open /home/dominic/dev/src/.goimportsignore: no such file or directory
2017/06/10 08:30:51.845561 scanning $GOPATH
2017/06/10 08:30:51.845676 scanning $GOROOT
2017/06/10 08:30:51.870174 scanned $GOROOT
2017/06/10 08:31:33.902214 scanned $GOPATH
2017/06/10 08:31:33.961465 aws candidate 1/39: github.com/aws/aws-sdk-go
2017/06/10 08:31:33.961486 aws candidate 2/39: github.com/aws/aws-sdk-go/aws
2017/06/10 08:31:33.961489 aws candidate 3/39: github.com/aws/aws-sdk-go/aws
2017/06/10 08:31:33.961498 aws candidate 4/39: github.com/99designs/aws-vault
2017/06/10 08:31:33.961502 aws candidate 5/39: github.com/aws/aws-sdk-go/service
2017/06/10 08:31:33.961513 aws candidate 6/39: github.com/aws/aws-sdk-go/aws/awserr
2017/06/10 08:31:33.961516 aws candidate 7/39: github.com/aws/aws-sdk-go/aws/awserr
2017/06/10 08:31:33.961518 aws candidate 8/39: github.com/aws/aws-sdk-go/aws/client
2017/06/10 08:31:33.961520 aws candidate 9/39: github.com/aws/aws-sdk-go/aws/client
2017/06/10 08:31:33.961523 aws candidate 10/39: github.com/aws/aws-sdk-go/awstesting
2017/06/10 08:31:33.961525 aws candidate 11/39: github.com/99designs/aws-vault/prompt
2017/06/10 08:31:33.961527 aws candidate 12/39: github.com/aws/aws-sdk-go/aws/awsutil
2017/06/10 08:31:33.961530 aws candidate 13/39: github.com/aws/aws-sdk-go/aws/awsutil
2017/06/10 08:31:33.961535 aws candidate 14/39: github.com/aws/aws-sdk-go/aws/request
2017/06/10 08:31:33.961537 aws candidate 15/39: github.com/aws/aws-sdk-go/aws/request
2017/06/10 08:31:33.961540 aws candidate 16/39: github.com/aws/aws-sdk-go/aws/session
2017/06/10 08:31:33.961545 aws candidate 17/39: github.com/aws/aws-sdk-go/aws/session
2017/06/10 08:31:33.961567 aws candidate 18/39: github.com/99designs/aws-vault/keyring
2017/06/10 08:31:33.961570 aws candidate 19/39: github.com/aws/aws-sdk-go/aws/defaults
2017/06/10 08:31:33.961578 aws candidate 20/39: github.com/aws/aws-sdk-go/aws/defaults
2017/06/10 08:31:33.961584 aws candidate 21/39: github.com/aws/aws-sdk-go/aws/endpoints
2017/06/10 08:31:33.961590 aws candidate 22/39: github.com/aws/aws-sdk-go/aws/endpoints
2017/06/10 08:31:33.961597 aws candidate 23/39: github.com/mattes/migrate/source/aws-s3
2017/06/10 08:31:33.961602 aws candidate 24/39: github.com/aws/aws-sdk-go/aws/credentials
2017/06/10 08:31:33.961607 aws candidate 25/39: github.com/aws/aws-sdk-go/aws/credentials
2017/06/10 08:31:33.961611 aws candidate 26/39: github.com/aws/aws-sdk-go/aws/ec2metadata
2017/06/10 08:31:33.961615 aws candidate 27/39: github.com/aws/aws-sdk-go/aws/ec2metadata
2017/06/10 08:31:33.961620 aws candidate 28/39: github.com/aws/aws-sdk-go/awstesting/mock
2017/06/10 08:31:33.961625 aws candidate 29/39: github.com/aws/aws-sdk-go/awstesting/unit
2017/06/10 08:31:33.961629 aws candidate 30/39: github.com/aws/aws-sdk-go/aws/corehandlers
2017/06/10 08:31:33.961634 aws candidate 31/39: github.com/aws/aws-sdk-go/aws/corehandlers
2017/06/10 08:31:33.961639 aws candidate 32/39: github.com/docker/docker/daemon/logger/awslogs
2017/06/10 08:31:33.961643 aws candidate 33/39: github.com/aws/aws-sdk-go/awstesting/integration
2017/06/10 08:31:33.961655 aws candidate 34/39: github.com/aws/aws-sdk-go/awstesting/performance
2017/06/10 08:31:33.961658 aws candidate 35/39: github.com/hashicorp/terraform/builtin/providers/aws
2017/06/10 08:31:33.961665 aws candidate 36/39: github.com/aws/aws-sdk-go/awsmigrate/awsmigrate-renamer
2017/06/10 08:31:33.961674 aws candidate 37/39: github.com/hashicorp/terraform/builtin/bins/provider-aws
2017/06/10 08:31:33.961688 aws candidate 38/39: github.com/aws/aws-sdk-go/awsmigrate/awsmigrate-renamer/gen
2017/06/10 08:31:33.961691 aws candidate 39/39: github.com/aws/aws-sdk-go/awsmigrate/awsmigrate-renamer/rename
2017/06/10 08:31:33.961731 loading exports in dir /home/dominic/dev/src/github.com/99designs/aws-vault (seeking package aws)
2017/06/10 08:31:33.961796 loading exports in dir /home/dominic/dev/src/github.com/aws/aws-sdk-go (seeking package aws)
2017/06/10 08:31:33.961819 loading exports in dir /home/dominic/dev/src/github.com/segmentio/lambda-warehouses/vendor/github.com/aws/aws-sdk-go/aws (seeking package aws)
2017/06/10 08:31:33.961858 loading exports in dir /home/dominic/dev/src/github.com/aws/aws-sdk-go/aws (seeking package aws)
2017/06/10 08:31:33.968551 loaded exports in dir /home/dominic/dev/src/github.com/segmentio/lambda-warehouses/vendor/github.com/aws/aws-sdk-go/aws (package aws): BackgroundContext, Bool, BoolMap, BoolSlice, BoolValue, BoolValueMap, BoolValueSlice, Config, Context, ErrMissingEndpoint, ErrMissingRegion, Float64, Float64Map, Float64Slice, Float64Value, Float64ValueMap, Float64ValueSlice, Int, Int64, Int64Map, Int64Slice, Int64Value, Int64ValueMap, Int64ValueSlice, IntMap, IntSlice, IntValue, IntValueMap, IntValueSlice, JSONValue, LogDebug, LogDebugWithHTTPBody, LogDebugWithRequestErrors, LogDebugWithRequestRetries, LogDebugWithSigning, LogLevel, LogLevelType, LogOff, Logger, LoggerFunc, NewConfig, NewDefaultLogger, NewWriteAtBuffer, ReadSeekCloser, ReaderSeekerCloser, RequestRetryer, SDKName, SDKVersion, SleepWithContext, String, StringMap, StringSlice, StringValue, StringValueMap, StringValueSlice, Time, TimeMap, TimeSlice, TimeUnixMilli, TimeValue, TimeValueMap, TimeValueSlice, URLHostname, UseServiceDefaultRetries, WriteAtBuffer
2017/06/10 08:31:33.983904 scan of dir /home/dominic/dev/src/github.com/aws/aws-sdk-go is not expected package aws (actually sdk)
2017/06/10 08:31:33.983954 loading exports in dir /home/dominic/dev/src/github.com/aws/aws-sdk-go/service (seeking package aws)
2017/06/10 08:31:33.984196 scan of dir /home/dominic/dev/src/github.com/99designs/aws-vault is not expected package aws (actually main)
2017/06/10 08:31:33.992548 scan of dir /home/dominic/dev/src/github.com/aws/aws-sdk-go/service is not expected package aws (actually service)
2017/06/10 08:31:34.046467 loaded exports in dir /home/dominic/dev/src/github.com/aws/aws-sdk-go/aws (package aws): BackgroundContext, Bool, BoolMap, BoolSlice, BoolValue, BoolValueMap, BoolValueSlice, Config, Context, ErrMissingEndpoint, ErrMissingRegion, Float64, Float64Map, Float64Slice, Float64Value, Float64ValueMap, Float64ValueSlice, Int, Int64, Int64Map, Int64Slice, Int64Value, Int64ValueMap, Int64ValueSlice, IntMap, IntSlice, IntValue, IntValueMap, IntValueSlice, JSONValue, LogDebug, LogDebugWithHTTPBody, LogDebugWithRequestErrors, LogDebugWithRequestRetries, LogDebugWithSigning, LogLevel, LogLevelType, LogOff, Logger, LoggerFunc, NewConfig, NewDefaultLogger, NewWriteAtBuffer, ReadSeekCloser, ReaderSeekerCloser, RequestRetryer, SDKName, SDKVersion, SleepWithContext, String, StringMap, StringSlice, StringValue, StringValueMap, StringValueSlice, Time, TimeMap, TimeSlice, TimeUnixMilli, TimeValue, TimeValueMap, TimeValueSlice, URLHostname, UseServiceDefaultRetries, WriteAtBuffer
2017/06/10 08:31:34.046530 loading exports in dir /home/dominic/dev/src/github.com/segmentio/lambda-warehouses/vendor/github.com/aws/aws-sdk-go/aws/awserr (seeking package aws)
2017/06/10 08:31:34.046877 scan of dir /home/dominic/dev/src/github.com/segmentio/lambda-warehouses/vendor/github.com/aws/aws-sdk-go/aws/awserr is not expected package aws (actually awserr)

// ...source code...

It's clearly spending all it's time on scanning the filesystem. And now that you mention it, my $GOPATH is on a mechanical drive, and my laptop has a hybrid drive, so it's likely got commonly-used files on the SSD cache.

My desktop actually uses an SSD for / and the HDD for /home, so I'll experiment by moving my $GOPATH somewhere on the SSD to see if that is the root of my problem.

@dominicbarnes
Copy link
Author

By moving my $GOPATH over to my SSD, the slowness I experienced was gone. I'm surprised I didn't think of the SSD/HDD difference earlier!

@bradfitz
Copy link
Contributor

goimports does try pretty hard to minimize disk I/O even for mechanical drives.

I'm a little surprised by the dups I see in:

2017/06/10 08:31:33.961602 aws candidate 24/39: github.com/aws/aws-sdk-go/aws/credentials
2017/06/10 08:31:33.961607 aws candidate 25/39: github.com/aws/aws-sdk-go/aws/credentials
2017/06/10 08:31:33.961611 aws candidate 26/39: github.com/aws/aws-sdk-go/aws/ec2metadata
2017/06/10 08:31:33.961615 aws candidate 27/39: github.com/aws/aws-sdk-go/aws/ec2metadata
2017/06/10 08:31:33.961620 aws candidate 28/39: github.com/aws/aws-sdk-go/awstesting/mock
2017/06/10 08:31:33.961625 aws candidate 29/39: github.com/aws/aws-sdk-go/awstesting/unit
2017/06/10 08:31:33.961629 aws candidate 30/39: github.com/aws/aws-sdk-go/aws/corehandlers
2017/06/10 08:31:33.961634 aws candidate 31/39: github.com/aws/aws-sdk-go/aws/corehandlers

I don't recall seeing that before. Might be worth looking into.

Maybe we need a "goimports -index" flag too to build an index ahead of time, so future goimports runs are faster.

I'm going to reopen this for investigation (at some point).

Help wanted.

@bradfitz bradfitz reopened this Jun 10, 2017
@bradfitz bradfitz added help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Performance labels Jun 10, 2017
@gopherbot
Copy link

Change https://golang.org/cl/53470 mentions this issue: x/tools/imports: Print dir of candidates instead of import path

@Merovius
Copy link
Contributor

Merovius commented Aug 5, 2017

I think the dupes are because of vendoring. They are all third-party packages and I can create these kind of dupes by just creating both $GOPATH/src/a/vendor/b and $GOPATH/src/b and then importing "b" from a package. Arguably, goimports should output the directory in the debug message, not the import path, to make it unambiguous. I've sent a CL.

I don't think it's an option to not visit both copies, though, because we can't really know whether they're the same version. I'd be happy to work on the mentioned -index flag, if someone tells me its worth doing. Would also be happy to investigate whether something else would be worth doing, but I have an SSD and a small GOPATH :)

gopherbot pushed a commit to golang/tools that referenced this issue Aug 6, 2017
The import path is ambiguous in the presence of vendoring (e.g. golang/go#20610)

Change-Id: I22f372b233b8554e3d9210b383a7df7a6a0f3eee
Reviewed-on: https://go-review.googlesource.com/53470
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
@gopherbot gopherbot added the Tools This label describes issues relating to any tools in the x/tools repository. label Sep 12, 2019
@heschi
Copy link
Contributor

heschi commented Nov 7, 2019

#22370 is somewhat related. I don't think there's much to do here other than the preindexing, which would be a big, complicated step. Closing; please comment if you disgree.

@heschi heschi closed this as completed Nov 7, 2019
@golang golang locked and limited conversation to collaborators Nov 6, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Performance Tools This label describes issues relating to any tools in the x/tools repository.
Projects
None yet
Development

No branches or pull requests

6 participants