godef takes ~2 seconds when used with go modules

[ahmetb]

godef seems to be unusually slow when used in a project using Go modules. This is making vscode-go extension slower.

Here's a repro that depends on 1 external module (and some more packages indirectly) and it takes ~1.7-3 seconds:

dir="$(mktemp -d)"

git clone https://github.com/grpc-ecosystem/grpc-health-probe "$dir"

cd "$dir"

git checkout 07cdf63

go mod download

time godef -t -f main.go -o 7099

this cursor position is a method in a directly imported package

/Users/ahmetb/go/pkg/mod/google.golang.org/[email protected]/health/grpc_health_v1/health.pb.go:151:2
Check func(ctx Context, in *HealthCheckRequest, opts ...CallOption) (*HealthCheckResponse, error)

godef -t -f main.go -o 7099  0.68s user 0.91s system 78% cpu 2.024 total

@rogpeppe @ianthehat

[ysoftman]

i had the same issue, try reinstall the godef using GO111MODULE=on environment variable.

GO111MODULE=on go get -u github.com/rogpeppe/godef

[ahmetb]

@ysoftman I don't think your recommendation helped (in fact it made the execution time worse for some reason). Given the repro I provided above, I ran these additional commands:

rm -rf ~/go/bin/godef

GO111MODULE=on go get -u github.com/rogpeppe/godef

$ which godef
~/go/bin/godef

time ~/go/bin/godef -t -f main.go -o 7099

the command above now takes somewhere between 3.3s and 5.5s per invocation.

[CannibalVox]

I've also seen massive latency increases on godef services since moving outside the gopath as part of the gomod update.

[mipearson]

Taking a quick look at this this morning (as this has also started hitting me in vscode):

• it's specific to the new implementation that uses golang.org/x/tools/go/packages
• the new implementation is used dynamically when go mod is detected, but can be forced with -new-implementation

My first run (OSX 2017 MBP) with @ahmetb's test case took 2 seconds, but subsequent runs took 0.4s, most of that in system. I haven't been able to reliably make it take multiple seconds again regardless of which offset I use.

I note that 0.3-0.5s is consistent for runs using the new implementation, whereas the old implementation is between 0.05 and 0.1s for me.

Running godef with -trace and then reading the trace shows that the 0.4s runs are spending all of their time running go itself:

Looking at the source for x/tools/packages, it looks like it's running go list. I'm not sure yet whether it's go list that is slow or whether it's the invocation of another command.

[mipearson]

Okay. Deleting godef and then rebuilding it with go get bumps the execution back up to 2s, which then drops to 0.7s on subsequent runs. It is definitely slower when installed using @ysoftman's suggestion.

GOMODENABLE=on go get -u github.com/rogpeppe/godef

time godef -t -f main.go -o 7077 -trace trace2.out
godef -t -f main.go -o 7077 -trace trace2.out  1.90s user 0.68s system 129% cpu 1.999 total

subsequent runs:
godef -t -f main.go -o 7077 -trace trace3.out  1.24s user 0.45s system 241% cpu 0.702 total
godef -t -f main.go -o 7077 -trace trace4.out  1.26s user 0.48s system 258% cpu 0.672 total
godef -t -f main.go -o 7077 -trace trace5.out  1.26s user 0.46s system 257% cpu 0.669 total
godef -t -f main.go -o 7077  1.21s user 0.47s system 253% cpu 0.661 total
godef -t -f main.go -o 7077  1.21s user 0.46s system 262% cpu 0.635 total

go get -u github.com/rogpeppe/godef

first run:
godef -t -f main.go -o 7077 -trace trace6.out  3.25s user 0.58s system 245% cpu 1.563 total

subsequent:
godef -t -f main.go -o 7077  0.41s user 0.34s system 205% cpu 0.367 total
godef -t -f main.go -o 7077  0.42s user 0.34s system 197% cpu 0.385 total
godef -t -f main.go -o 7077  0.42s user 0.34s system 194% cpu 0.393 total
godef -t -f main.go -o 7077 -trace trace6.out  0.43s user 0.34s system 203% cpu 0.378 total
godef -t -f main.go -o 7099 -trace trace6.out  0.43s user 0.34s system 198% cpu 0.385 total

Note that specifying -trace does not seem to affect execution time in the above measurements

[mipearson]

Confirming:

If I put grpc-health-probe in my GOPATH, then remove its go.mod/go.sum files, I get consistent < 0.1s times regardless of whether it's my first run of that godef binary or not:

within go path, go.mod/sum removed

rm ~/go/bin/godef
go get -u github.com/rogpeppe/godef
# first run
godef -t -f main.go -o 7099 -trace trace.out  0.04s user 0.03s system 103% cpu 0.059 total
# subsequent
godef -t -f main.go -o 7099 -trace trace.out  0.04s user 0.03s system 97% cpu 0.073 total
godef -t -f main.go -o 7099 -trace trace.out  0.04s user 0.03s system 100% cpu 0.074 total
godef -t -f main.go -o 7099 -trace trace.out  0.03s user 0.02s system 106% cpu 0.055 total

[mipearson]

A half-day of deep diving later:

1. godef uses golang.org/x/tools/go/packages in directories containing a go.mod to resolve things as gomodules make things non-trivial
2. packages calls out to go list to get information about packages
3. go list, in certain situations, will trigger a recompile of packages - this is most likely what's causing the 8-10s runs above
4. most times go list will instead be able to use the build cache - this is where we get the 0.3s runs
5. go list does a lot of very, very deep diving to do what it does - at a point beyond where I'm comfortable judging whether said diving is necessary for the functionality of godef or not

Looking through the traces and so forth shows lots of file opens & reads, even when the build cache is used.

My guess is that godef's original implementation could afford to be quite specialised about what it interrogated, and was thus fast. As the current implementation depends on external (and more generic purpose) tooling, that tooling could potentially be doing a lot more than it otherwise needs to be doing to get the information that godef needs.

[darshanime]

godef seems to speed up after running go mod vendor, I think because it doesn't have to do all the extra work🔝