x/tools/gopls: slow imports / formatting

[stamblerre]

@zikaeroh reported slow import organization and formatting in #35388. Filing this issue to follow up. If anyone else experiences similar issues, please comment below and attach gopls logs if possible.

[heschi]

Note that we need verboseOutput set for the logs to be much use for this.

[zikaeroh]

Thanks for following up. Essentially, my workflow is the tried and true "hit save and run goimports", i.e. I want formatting, import sorting, and adding of missing imports on whatever code I save.

What I'm observing is that import sorting and adding of missing imports isn't much faster than goimports. And, when combined with code that needs to be formatted, I'm seeing the formatting happen much much later (a few seconds after imports are fixed), or not at all (and another save then triggers it).

Here is a gist with two logs where I tried to perform similar actions, one with gopls enabled as the formatter, and another where I disable those features leading them to fallback to vscode-go running goimports. I did enable verboseOutput as requested.

https://gist.github.com/zikaeroh/fc08a33efd1f14aab420789a978d4205

Additionally, here are two screencasts showing the kind of slowness I'm referring to. These are not the same as what's in the logs, but I can try and produce matching logs/screencasts if needed.

With goimports: https://streamable.com/pwmgs

With gopls: https://streamable.com/id6ce

I wasn't able to capture the "imports get sorted, then a few seconds later the formatting happens" in the gopls screencast (for some reason), but I'll try to capture it if I see it pop up.

My go-related config:

    "go.useLanguageServer": true,
    "go.alternateTools": {
        "go-langserver": "gopls"
    },
    "go.languageServerExperimentalFeatures": {
        "format": true,
        "autoComplete": true,
        "diagnostics": true,
        "goToDefinition": true,
        "hover": true,
        "signatureHelp": true,
        "goToTypeDefinition": true,
        "documentSymbols": true,
    },
    "go.buildOnSave": "off",
    "go.vetOnSave": "off",
    "[go]": {
        "editor.snippetSuggestions": "none",
        "editor.formatOnSave": true,
        // "editor.formatOnSave": false,
        "editor.codeActionsOnSave": {
            "source.organizeImports": true
        },
        "editor.codeActionsOnSaveTimeout": 3000
    },
    "gopls": {
        "usePlaceholders": false,
        "completeUnimported": true,
        "watchFileChanges": true,
        "deepCompletion": true,
        "go-diff": true,
        // "staticcheck": true,
        "verboseOutput": true,
    },
    "go.languageServerFlags": [
        "-rpc.trace", // for more detailed debug logging
        "-logfile",
        "/home/jake/gopls.log",
        "serve",
        "--debug=localhost:6060", // to investigate memory usage, see profiles 
    ],

[zikaeroh]

Since the screencaps don't show keystrokes, the only way to show the save events is to look at the tab indicator icon VS Code shows for unsaved files. Hopefully the logs will show didSave events to help line things up within those logs, but if it's critical I can attempt to take a screencap with some keypresses.

[heschi]

Sorry for the delay on this, last week was hectic. Needless to say, I still can't reproduce the problem...

Not sure what to make of this yet. I don't think it has all that much to do with imports per se. Request 48, for example, takes 694ms. But almost all of that time is actually just spent waiting for a previous request to finish a go/packages.Load call.

[Trace - 21:54:14.256 PM] Sending request 'textDocument/codeAction - (48)'.
Params: {"textDocument":{"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/flags/botflags/botargs.go"},"range":{"start":{"line":21,"character":0},"end":{"line":21,"character":0}},"context":{"diagno>


[Trace - 21:54:14.300 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/06 21:54:14 42.640563ms for GOROOT=/usr/lib/go GOPATH=/home/jake/go GO111MODULE= PWD=/home/jake/zikaeroh/hortbot/hortbot go \"env\" \"GOMOD\", stderr: \u003c\u003c\u003e\u00>


[Trace - 21:54:14.437 PM] Sending request 'textDocument/documentLink - (49)'.
Params: {"textDocument":{"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/flags/botflags/botargs.go"}}


[Trace - 21:54:14.516 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/06 21:54:14 245.449982ms for GOROOT=/usr/lib/go GOPATH=/home/jake/go GO111MODULE= PWD=/home/jake/zikaeroh/hortbot/hortbot go \"list\" \"-m\" \"-json\" \"all\", stderr: \u003>


[Trace - 21:54:14.729 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/06 21:54:14 609.25391ms for GOROOT=/usr/lib/go GOPATH=/home/jake/go GO111MODULE= PWD=/home/jake/zikaeroh/hortbot/hortbot go \"list\" \"-e\" \"-json\" \"-compiled=true\" \"-t>


[Trace - 21:54:14.731 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/06 21:54:14 go/packages.Load\n\tpackages = 1"}


[Trace - 21:54:14.731 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/06 21:54:14 go/packages.Load\n\tpackage = github.com/hortbot/hortbot/internal/cli/flags/botflags\n\tfiles = [/home/jake/zikaeroh/hortbot/hortbot/internal/cli/flags/botflags/>


[Trace - 21:54:14.732 PM] Received notification 'textDocument/publishDiagnostics'.
Params: {"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/flags/botflags/botargs.go","version":11,"diagnostics":[]}


[Trace - 21:54:14.949 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/06 21:54:14 go/packages.Load\n\tpackages = 1"}


[Trace - 21:54:14.949 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/06 21:54:14 go/packages.Load\n\tpackage = github.com/hortbot/hortbot/internal/cli/flags/botflags\n\tfiles = [/home/jake/zikaeroh/hortbot/hortbot/internal/cli/flags/botflags/>


[Trace - 21:54:14.950 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/06 21:54:14 fixImports(filename=\"/home/jake/zikaeroh/hortbot/hortbot/internal/cli/flags/botflags/botargs.go\"), abs=\"/home/jake/zikaeroh/hortbot/hortbot/internal/cli/flags>


[Trace - 21:54:14.951 PM] Received response 'textDocument/codeAction - (48)' in 694ms.
Result: {}

Request 19 is also slow, in the actual goimports code this time, but that's the first scan before anything is cached, so I don't think there's much to be learned there.

Sorry, I think I'm going to need more logs to nail this down. If you can give a snippet from a natural occurrence, rather than a forced repro, that would be ideal. But I understand that might not be convenient, so whatever you can do.

[heschi]

One note, actually -- changing the imports block like this is a worst case for gopls because it triggers Load calls. If you can get this kind of thing to happen by changing non-imports, that's much more worrying/interesting. If it only happens in imports, then I'm tempted to say that people are unlikely to add imports multiple times per second.

[zikaeroh]

I guess I don't know what distinguishes a "natural occurrence", then... It's pretty common when I'm writing code that I both have a missing import (new code, new imports) and formatting to clean up (extra newlines, spacing). I find myself having to wait / save again after imports get sorted to get things to the right state.

I can just bulk record logs as I work on something, and hope to find something, but know that I definitely won't be able to do any sort of screencasting.

changing non-imports

What do you mean by this? Specifically just changing anything but imports? Because I can't really say I experience slowness if imports aren't changing. A plain format is fast. It's the two together (i.e. goimports-style formatting) where I see slowness. Presumably, it's going to be fast if gopls never has to deal with any new packages.

[heschi]

I can just bulk record logs as I work on something, and hope to find something, but know that I definitely won't be able to do any sort of screencasting.

That's totally fine -- the log is sufficient. I don't really need the screencasts at all for this, I should be able to piece things together from the logs if I absolutely have to.

It's the two together (i.e. goimports-style formatting) where I see slowness.

Yeah, I guess what I meant was that if you're doing the kind of stuff in the screencast, changing imports very fast, then I'm not surprised if gopls starts tripping over itself. A less synthetic example would help make sure I'm focused on the right problem.

I find myself having to wait / save again after imports get sorted to get things to the right state.

Maybe this is the actual problem. Would you be so worried about the performance if you didn't have to do things twice? I would be interested to see a log of formatting not happening, maybe as a separate bug.

FWIW, with completeUnimported all this should matter less, because the import statement will show up in the right place before you save.

[zikaeroh]

Yeah, I guess what I meant was that if you're doing the kind of stuff in the screencast, changing imports very fast, then I'm not surprised if gopls starts tripping over itself. A less synthetic example would help make sure I'm focused on the right problem.

The "very fast" is really only because I'm trying to keep the screencast short. I can delete something, wait a bit, then save and it'd be slow.

Would you be so worried about the performance if you didn't have to do things twice?

Maybe not, but in the past I had been getting format + import all in one go. Since the race condition was fixed, I haven't seen it happen in one step anymore. Maybe fixing the bug means that my editor's no longer applying two changes, or something, and it's picking organize first and just not bothering to try and finish the rest.

FWIW, with completeUnimported all this should matter less, because the import statement will show up in the right place before you save.

I assume by this you mean accepting a completion item which includes a TextEdit that adds the import. There are cases where I don't get those at all (completely missing the thing I want even though it's somewhere in my deps), or they are a bunch of things I'm not interested in (even though I've used many of them in my project already), where it's better for me to simply not accept the completion, write it out by hand, then save.

I believe there's an open issue about sorting those better (i.e. sorting direct module dependencies first), which would help somewhat. A concrete example is when I try to write a new test file, then type assert. trying to use gotest.tools/v3/assert, only to get suggested completely different assert libraries, and even the non-module v2 gotest.tools/assert. If I accidentally select the wrong one, it's a pain to undo because go.mod will have already changed. Even worse when I try to just import log or something because there's a million log packages.