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/gopls: performance regression on monorepos with gopls@v0.15.0+ #66647

Open
hitzhangjie opened this issue Mar 18, 2024 · 55 comments
Open
Assignees
Labels
gopls/performance Issues related to gopls performance (CPU, memory, etc). gopls Issues related to the Go language server, gopls. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Milestone

Comments

@hitzhangjie
Copy link
Contributor

What version of Go, VS Code & VS Code Go extension are you using?

Version Information
  • Run go version to get version of Go from the VS Code integrated terminal.
    • go version go1.21.6 linux/amd64
  • Run gopls -v version to get version of Gopls from the VS Code integrated terminal.
    • Build info

golang.org/x/tools/gopls v0.15.2
golang.org/x/tools/gopls@v0.15.2 h1:4JKt4inO8JaFW3l/Fh9X1k/5JQn+iUOpdc4/Lpi0mOs=
github.com/BurntSushi/toml@v1.2.1 h1:9F2/+DoOYIOksmaJFPw1tGFy1eDnIJXg+UHjuD8lTak=
github.com/google/go-cmp@v0.6.0 h1:ofyhxvXcZhMsU5ulbFiLKl/XBFqE1GSq7atu8tAmTRI=
golang.org/x/exp/typeparams@v0.0.0-20221212164502-fae10dda9338 h1:2O2DON6y3XMJiQRAS1UWU+54aec2uopH3x7MAiqGW6Y=
golang.org/x/mod@v0.15.0 h1:SernR4v+D55NyBH2QiEQrlBAnj1ECL6AGrA5+dPaMY8=
golang.org/x/sync@v0.6.0 h1:5BMeUDZ7vkXGfEr1x9B4bRcTH4lpkTkpdh0T/J+qjbQ=
golang.org/x/telemetry@v0.0.0-20240209200032-7b892fcb8a78 h1:vcVnuftN4J4UKLRcgetjzfU9FjjgXUUYUc3JhFplgV4=
golang.org/x/text@v0.14.0 h1:ScX5w1eTa3QqT8oi6+ziP7dTV1S2+ALU0bI+0zXKWiQ=
golang.org/x/tools@v0.18.1-0.20240311201521-78fbdeb61842 h1:No0LMXYFkp3j4oEsPdtY8LUQz33gu79Rm9DE+izMeGQ=
golang.org/x/vuln@v1.0.1 h1:KUas02EjQK5LTuIx1OylBQdKKZ9jeugs+HiqO5HormU=
honnef.co/go/tools@v0.4.6 h1:oFEHCKeID7to/3autwsWfnuv69j3NsfcXbvJKuIcep8=
mvdan.cc/gofumpt@v0.6.0 h1:G3QvahNDmpD+Aek/bNOLrFR2XC6ZAdo62dZu65gmwGo=
mvdan.cc/xurls/v2@v2.5.0 h1:lyBNOm8Wo71UknhUs4QTFUNNMyxy2JEIaKKo0RWOh+8=
go: go1.21.6

  • Run code -v or code-insiders -v to get version of VS Code or VS Code Insiders.
    • 1.87.2
      863d2581ecda6849923a2118d93a088b0745d9d6
      x64
  • Check your installed extensions to get the version of the VS Code Go extension
    • v0.41.2
  • Run Ctrl+Shift+P (Cmd+Shift+P on Mac OS) > Go: Locate Configured Go Tools command.

Share the Go related settings you have added/edited

Run Preferences: Open Settings (JSON) command to open your settings.json file.
Share all the settings with the go. or ["go"] or gopls prefixes.

"go.editorContextMenuCommands": {
"addImport": false,
"addTags": false,
"benchmarkAtCursor": true,
"debugTestAtCursor": false,
"fillStruct": true,
"playground": false,
"testAtCursor": false,
"testCoverage": false,
"testFile": true,
"testPackage": true,
"toggleTestFile": false
},
"go.formatTool": "default",
"go.goroot": "/usr/local/go",
"go.lintOnSave": "off",
"go.lintTool": "golangci-lint",
"go.testEnvFile": "",
"go.testEnvVars": {},
"go.testFlags": [
"-v",
"-count=1"
],
"go.toolsEnvVars": {},
"go.toolsManagement.autoUpdate": true,
"gopls": {
"formatting.local": "my repo module"
},

Describe the bug

My project is organized as monorepo including nearly 70 sub projects, its structure is as following:

myproject/
go.mod
go.sum
subproject1/ (no separate go.mod)
subproject2/ (no separate go.mod)
...
subprojectN/ (no separate go.mod)
vendor/

my development environment is:

  • Host: windows11 + vscode (32GB RAM, CPU i7, 1TB SSD)
  • Remote: vscode remote + Linux (cloud machine with 64GB RAM, 32Core CPU, 300GB local disk)
  • The network is within the inner network of my enterprise, the latency is very low.

When I do some refactor, or jump to the definition, documentation, auto completion, it responds very very very slowly, nearly more than 30 seconds.

Steps to reproduce the behavior:

I cannot share the big monorepo to you, but I can investigate by myself if you could give me some suggestions about how to do.

Thank you.

@hitzhangjie hitzhangjie changed the title on monorepo, vscode-go extension extremely slow when find the definition, documentation, auto completion performance: on monorepo, vscode-go extension extremely slow when find the definition, documentation, auto completion Mar 18, 2024
@zhangfannie
Copy link
Contributor

I encountered the same problem recently, the response was extremely slow.

@findleyr
Copy link
Contributor

Hi, is this issue describing a recent regression, or has this always been a problem?

@findleyr findleyr added gopls Issues related to the Go language server, gopls. gopls/performance Issues related to gopls performance (CPU, memory, etc). and removed Documentation labels Mar 18, 2024
@findleyr
Copy link
Contributor

To be more specific: do you experience this problem with gopls@v0.14.2?

go install golang.org/x/tools/gopls@v0.14.2

If so, then I think we can fix the regression. If not, there may still be things we can do to get gopls working better for you on your monorepo (albeit perhaps with some features being limited).

@zhangfannie
Copy link
Contributor

zhangfannie commented Mar 19, 2024

I encountered the same problem recently, the response was extremely slow.

The issue I encountered was caused by a problem with GOROOT in my environment, and it is now working normally. Sorry to cause any disturbance.
BTW, I uses gopls@v0.15.2.
Thank you.

@findleyr findleyr added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Mar 19, 2024
@findleyr
Copy link
Contributor

Another thing you can do is share details about the gopls process when you perform one of these operations. Is gopls using a lot of CPU for the entire time you're waiting? How much memory does gopls use? This will help us confirm that the problem is indeed with gopls (most likely), and not something in the extension host.

@gordallott
Copy link

I don't want to hog someone else's (apparently resolved) issue but I have extreme monorepo performance issues with gopls, switching to gopls 0.14.2 resolved the issues

with any later version, completion is very slow (multiple seconds to bring up imports after using Add Import, multiple seconds to bring up symbols after typing <import>.. Saving a file takes about 5-6 seconds

there doesn't seem to by any memory/cpu use difference between 0.14.2 and other versions, the only difference seems to be that there are multiple go list commands that run and take a long time to return during pretty much any operation when using a version greater than 0.14.2

@adonovan
Copy link
Member

@zhangfannie, do you also observe that the problem goes away when switching back to v0.14?

@findleyr
Copy link
Contributor

It sounds like @gordallott's issues are related to goimports changes in gopls@v0.15.0+.

I think there's definitely something more going on here, so thank you @gordallott for chiming in. Can you share more about your workspace? Do you have multiple modules? Do you use go.work files?

Also, can you share an example of the go list commands you observe?

@gordallott
Copy link

sure, single module for the entire repo, some git submodules but not to other go repos. no go.work files

go list -tags debug,cloud -overlay=/tmp/gopackages-3706371482/overlay.json -e -json=Name,ImportPath,Error,Dir,GoFiles,IgnoredGoFiles,IgnoredOtherFiles,CFiles,CgoFiles,CXXFiles,MFiles,HFiles,FFiles,SFiles,SwigFiles,SwigCXXFiles,SysoFiles,TestGoFiles,XTestGoFiles,CompiledGoFiles,Export,DepOnly,Imports,ImportMap,TestImports,XTestImports,ForTest,DepsErrors,Module,EmbedFiles -compiled=true -test=true -export=false -deps=true -find=false -pgo=off -tags debug,cloud -- /home/gord/gordallott/axiom/... builtin

these go list cmds either don't execute with 1.14.2 - or they complete fast enough that my hacky ps monitoring didn't catch them

if i run that go list cmd with time, (and without the overlay because that part errors with file not found), i get

go list -tags debug,cloud -e  -compiled=true -test=true -export=false    -tag  3.00s user 1.72s system 280% cpu 1.682 total

@zhangfannie
Copy link
Contributor

@zhangfannie, do you also observe that the problem goes away when switching back to v0.14?

Sorry for the late reply, gopls@v0.14 can work in my environment as well. Thank you.

@hitzhangjie
Copy link
Contributor Author

I reinstall gopls@v0.14.2 instead of the latest v0.15.2, the problem gone.

@findleyr
Copy link
Contributor

Hi @gordallott, @zhangfannie, and @hitzhangjie.

I have been traveling, but am back now and this issue is my top priority: the changes in gopls@v0.15.0+ were not intended to affect performance for most users. There is an intentional performance hit if you are, for example, on linux and open a foo_windows.go file, because previously gopls would not be able to load the windows build, and now it can. But that should only happen if you have multiple logical builds open in your editor. It sounds like what you are encountering is an across-the-board regression in your repositories, which is almost certainly a bug.

I am glad that downgrading allows you to continue working. However, since you are able to reproduce the regression, it would be enormously helpful if you are able to occasionally help me investigate over the next week, by trying out different versions of gopls.

Quick question, before I dig in more: are you all on Windows? I see that @hitzhangjie is, but what about @gordallott and @zhangfannie? I have seen some similar sounding feedback in our recent survey results, almost all from windows users.

@gordallott
Copy link

hey no sorry, I'm on linux, I'm running my vscode (on linux) through a vscode remote to a lxc container where gopls runs

host/container info

  ~ uname -a
Linux pumbaa 6.5.0-26-generic golang/vscode-go#26~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Tue Mar 12 10:22:43 UTC 2 x86_64 x86_64 x86_64 GNU/Linux

the only other special case is that I'm running zfs as my filesystem - nothing special enabled in zfs configurations, not even encryption.

No other performance problems in any other applications

@findleyr
Copy link
Contributor

Thanks @gordallott. And just to check: is your zfs configured to be case sensitive? I think that's the default, but since it's very plausible that this bug could be related to case insensitive file systems, I wanted to confirm.

No other performance problems in any other applications

No, if gopls@v0.14.2 works well, then this is certainly a gopls bug.

@gordallott
Copy link

my zfs is indeed case sensitive

@findleyr findleyr changed the title performance: on monorepo, vscode-go extension extremely slow when find the definition, documentation, auto completion x/tools/gopls: performance regression on monorepos with gopls@v0.15.0+ Apr 2, 2024
@findleyr
Copy link
Contributor

findleyr commented Apr 2, 2024

Thanks. Since this is clearly a gopls issue, transferring to the Go issue tracker so that it can be included in the gopls@v0.15.3 milestone.

I will get to the bottom of this.

@findleyr findleyr transferred this issue from golang/vscode-go Apr 2, 2024
@findleyr findleyr added this to the gopls/v0.15.3 milestone Apr 2, 2024
@findleyr findleyr self-assigned this Apr 2, 2024
@findleyr
Copy link
Contributor

findleyr commented Apr 3, 2024

If someone experiencing these problems is able to run gopls@v0.15.2 with the following settings, and report whether they still experience performance issues, it would be helpful:

settings.json

{
    "gopls": {
        "zeroConfig": false,
        "analyses": {
            "nilness": false
        }
    }
}

@jacobmischka
Copy link

jacobmischka commented Apr 4, 2024

Is zeroConfig a valid setting? I don't see it in the docs, and no matter which type of capitalization I use it doesn't like it.

I just updated gopls with go install golang.org/x/tools/gopls@latest.

LSP[gopls] Invalid settings: unexpected gopls setting "zeroconfig"

@findleyr
Copy link
Contributor

findleyr commented Apr 4, 2024

@jacobmischka yes it should be a valid setting (with "zeroConfig" as casing) if you are using gopls@v0.15.0+. It is a hidden setting to disable the dynamic workspace heuristics added in v0.15.0, specifically so that we can do this type of investigation. The setting will be removed in future versions.

@jacobmischka
Copy link

It doesn't like it :/ I also tried zero_config as well. I'm using neovim with lspconfig, if that matters? It accepted analyses just fine.

LSP[gopls] Invalid settings: unexpected gopls setting "zeroConfig"

@findleyr
Copy link
Contributor

findleyr commented Apr 5, 2024

@jacobmischka thanks for catching that -- yes the detailed traces may contain paths. For what it's worth, you can remove all those as they are not relevant.

You can email me at rfindley@google.com.

@jacobmischka
Copy link

Ah okay, I stripped them out: https://gist.github.com/jacobmischka/b47b7b4f7f93d77d2b864f64443b1711

@findleyr
Copy link
Contributor

findleyr commented Apr 5, 2024

@jacobmischka you it looks like the package you're working on is taking 1.8s to type check (!!):

        09:44:28.062 start cache.typeCheckBatch.checkPackage 
        09:44:29.890 end cache.typeCheckBatch.checkPackage (+1.827515584s) 

That's an inordinate amount of time. For reference, the runtime package (which is the slowest package to type check in the standard library) takes around 80ms to type check on my machine.

Can you tell me anything else about that package? Is it very large? Does it have very large files, or a lot of declarations? Does it have generated code? It may be that you're bumping up against something quadratic in the type checker that doesn't matter for other packages.

I suspect that if you close all files and just open a file in a different package, gopls will feel faster.

I'm extremely curious as to how a package could be so slow to type check. A profile would be very useful. Now that you have the debug server running, you can grab a profile by running the following command:

go tool pprof http://localhost:8080/debug/pprof/profile?seconds=10

Then navigate to your editor and perform some of the slow operations. After 10s, you'll be dumped into a pprof shell. I'd love to see the content of top 50 -cum checkPackage.

@jacobmischka
Copy link

This project has quite a lot of generated code, yes (much to my dismay). Some of the generated files are quite large (almost 140k lines, lol), and there are a fair number of large dependencies in the project.

Here's the profile, let me know if you'd like me to run it again or for longer duration.

Trace profile checkPackage
File: gopls
Type: cpu
Time: Apr 5, 2024 at 10:13am (CDT)
Duration: 10.11s, Total samples = 11.82s (116.95%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top 50 -cum checkPackage
Active filters:
   focus=checkPackage
Showing nodes accounting for 4.70s, 39.76% of 11.82s total
Dropped 87 nodes (cum <= 0.06s)
Showing top 50 nodes out of 73
      flat  flat%   sum%        cum   cum%
         0     0%     0%      5.35s 45.26%  go/types.(*Checker).Files (inline)
         0     0%     0%      5.35s 45.26%  go/types.(*Checker).checkFiles
         0     0%     0%      5.35s 45.26%  go/types.(*Checker).funcBody
         0     0%     0%      5.35s 45.26%  go/types.(*Checker).funcDecl.func1
         0     0%     0%      5.35s 45.26%  go/types.(*Checker).processDelayed
     0.01s 0.085% 0.085%      5.35s 45.26%  go/types.(*Checker).stmt
         0     0% 0.085%      5.35s 45.26%  go/types.(*Checker).stmtList
         0     0% 0.085%      5.35s 45.26%  golang.org/x/sync/errgroup.(*Group).Go.func1
         0     0% 0.085%      5.35s 45.26%  golang.org/x/tools/gopls/internal/cache.(*Snapshot).forEachPackageInternal.func2
         0     0% 0.085%      5.35s 45.26%  golang.org/x/tools/gopls/internal/cache.(*typeCheckBatch).checkPackage
         0     0% 0.085%      5.35s 45.26%  golang.org/x/tools/gopls/internal/cache.(*typeCheckBatch).handleSyntaxPackage
         0     0% 0.085%      5.28s 44.67%  go/types.(*Checker).rawExpr
         0     0% 0.085%      5.27s 44.59%  go/types.(*Checker).exprInternal
         0     0% 0.085%      5.22s 44.16%  go/types.(*Checker).callExpr
         0     0% 0.085%      5.02s 42.47%  go/types.(*Checker).arguments
         0     0% 0.085%      4.98s 42.13%  go/types.(*Checker).assignment
         0     0% 0.085%      4.96s 41.96%  go/types.(*Checker).implements
     0.02s  0.17%  0.25%      4.96s 41.96%  go/types.(*Checker).missingMethod
         0     0%  0.25%      4.96s 41.96%  go/types.(*operand).assignableTo
     0.03s  0.25%  0.51%      4.85s 41.03%  go/types.lookupFieldOrMethodImpl
         0     0%  0.51%      3.62s 30.63%  go/types.(*Checker).multiExpr
         0     0%  0.51%      3.44s 29.10%  go/types.(*Checker).initVars
         0     0%  0.51%      3.35s 28.34%  go/types.(*Checker).shortVarDecl
     0.04s  0.34%  0.85%      2.54s 21.49%  runtime.growslice
     0.50s  4.23%  5.08%      2.36s 19.97%  runtime.mallocgc
     0.03s  0.25%  5.33%      1.93s 16.33%  go/types.(*Named).lookupMethod
     0.99s  8.38% 13.71%      1.93s 16.33%  go/types.lookupMethod
     1.83s 15.48% 29.19%      1.83s 15.48%  runtime.memclrNoHeapPointers
         0     0% 29.19%      1.18s  9.98%  go/types.(*Checker).expr
         0     0% 29.19%      0.97s  8.21%  go/types.(*Checker).unary
     0.88s  7.45% 36.63%      0.94s  7.95%  go/types.(*object).sameId
         0     0% 36.63%      0.91s  7.70%  runtime.(*mcache).nextFree
         0     0% 36.63%      0.91s  7.70%  runtime.(*mcache).refill
         0     0% 36.63%      0.91s  7.70%  runtime.(*mcentral).cacheSpan
         0     0% 36.63%      0.91s  7.70%  runtime.(*mcentral).grow
         0     0% 36.63%      0.89s  7.53%  runtime.(*mspan).initHeapBits
         0     0% 36.63%      0.77s  6.51%  go/types.(*Checker).simpleStmt (inline)
         0     0% 36.63%      0.76s  6.43%  go/types.concat (inline)
         0     0% 36.63%      0.29s  2.45%  go/types.(*Checker).assignVars
     0.25s  2.12% 38.75%      0.25s  2.12%  runtime.memmove
         0     0% 38.75%      0.20s  1.69%  go/types.(*Checker).rangeStmt
         0     0% 38.75%      0.17s  1.44%  go/types.consolidateMultiples
         0     0% 38.75%      0.16s  1.35%  go/types.(*Checker).genericExprList
     0.05s  0.42% 39.17%      0.14s  1.18%  go/types.(*comparer).identical
         0     0% 39.17%      0.14s  1.18%  go/types.Identical (partial-inline)
         0     0% 39.17%      0.14s  1.18%  go/types.lookupType
     0.07s  0.59% 39.76%      0.14s  1.18%  runtime.mapassign
         0     0% 39.76%      0.11s  0.93%  go/types.(*Checker).exprOrType
         0     0% 39.76%      0.11s  0.93%  runtime.newobject (partial-inline)
         0     0% 39.76%      0.09s  0.76%  go/types.(*Checker).selector

@jacobmischka
Copy link

We're trying to get the codegen split into more smaller files to see if that helps, will report back.

@findleyr
Copy link
Contributor

findleyr commented Apr 5, 2024

Thanks very much @jacobmischka for following up until we understood your problem. I think I understand it now, and have filed it as #66699. I think it's probably unrelated to the regressions reported by others in this issue, so let's continue discussion on #66699.

For now, I think if you move the codegen into a different package that you don't frequently work on, it should improve your editing experience significantly. Of course, it's not great for your tools to have to force you into a different package layout.

@gordallott
Copy link

If someone experiencing these problems is able to run gopls@v0.15.2 with the following settings, and report whether they still experience performance issues, it would be helpful:

settings.json

{
    "gopls": {
        "zeroConfig": false,
        "analyses": {
            "nilness": false
        }
    }
}

performance of gopls @ v0.15.2 seems the same with or without this config, unaffected by it. Both the slowness on save and the symbol autocomplete are both as slow as without the config

@findleyr
Copy link
Contributor

findleyr commented Apr 9, 2024

Hi folks, I've looked into potential performance regressions quite a bit and have some theories, though no obvious root cause (https://go.dev/cl/577695 may help).

It would be very helpful if someone experiencing problems with gopls@v0.15.2 (but not gopls@v0.14.2) could do the following:

  1. Start gopls with -debug=localhost:8080.
  2. Visit http://localhost:8080/trace/
  3. Copy the entire first section (Trace Information) and share it here. You don't need to include Recent Spans, as that will include things like package and file names that you may not want to share.

With this information, I'll be able to see which operations are slow and which are fast, and that will help me narrow down a culprit. Thanks.

@gopherbot
Copy link

Change https://go.dev/cl/577695 mentions this issue: gopls/internal/server: avoid duplicate diagnoses and loads

@gordallott
Copy link

gopls v0.15.2 with trace info - copied after a slow symbol lookup, followed by a slow save

Trace Information
[$/cancelRequest](http://localhost:8088/trace/$/cancelRequest) last: 24.024µs, longest: 103.351µs
[$/progress](http://localhost:8088/trace/$/progress) last: 71.932µs, longest: 71.932µs
[$/setTrace](http://localhost:8088/trace/$/setTrace) last: 1.976277706s, longest: 1.976277706s
[Server.diagnose](http://localhost:8088/trace/Server.diagnose) last: 2.389583648s, longest: 2.389583648s
[Server.diagnoseChangedFiles](http://localhost:8088/trace/Server.diagnoseChangedFiles) last: 110.146877ms, longest: 139.436516ms
[Server.diagnoseSnapshot](http://localhost:8088/trace/Server.diagnoseSnapshot) last: 3.501964695s, longest: 3.501964695s
[Server.publishDiagnostics](http://localhost:8088/trace/Server.publishDiagnostics) last: 495.977µs, longest: 2.13202ms
[cache.ModTidy](http://localhost:8088/trace/cache.ModTidy) last: 702.045932ms, longest: 738.339073ms
[cache.ParseGoSrc](http://localhost:8088/trace/cache.ParseGoSrc) last: 1.838806ms, longest: 16.848476ms
[cache.ParseMod](http://localhost:8088/trace/cache.ParseMod) last: 963.82µs, longest: 963.82µs
[cache.forEachPackage](http://localhost:8088/trace/cache.forEachPackage) last: 211.440881ms, longest: 211.440881ms
[cache.importsState.refreshProcessEnv](http://localhost:8088/trace/cache.importsState.refreshProcessEnv) last: 1.157029128s, longest: 1.157029128s
[cache.importsState.runProcessEnvFunc](http://localhost:8088/trace/cache.importsState.runProcessEnvFunc) last: 1.018697ms, longest: 83.461464ms
[cache.readFile](http://localhost:8088/trace/cache.readFile) last: 51.52µs, longest: 7.862855ms
[cache.resolveImportGraph](http://localhost:8088/trace/cache.resolveImportGraph) last: 66.607404ms, longest: 128.008807ms
[cache.sharedModCache.refreshDir](http://localhost:8088/trace/cache.sharedModCache.refreshDir) last: 158.513898ms, longest: 158.513898ms
[cache.snapshot.ModTidy](http://localhost:8088/trace/cache.snapshot.ModTidy) last: 702.123382ms, longest: 738.390246ms
[cache.snapshot.PackageDiagnostics](http://localhost:8088/trace/cache.snapshot.PackageDiagnostics) last: 211.502932ms, longest: 211.502932ms
[cache.snapshot.clone](http://localhost:8088/trace/cache.snapshot.clone) last: 79.037µs, longest: 33.94325ms
[cache.snapshot.load](http://localhost:8088/trace/cache.snapshot.load) last: 1.981050925s, longest: 2.155579202s
[cache.typeCheckBatch.checkPackage](http://localhost:8088/trace/cache.typeCheckBatch.checkPackage) last: 51.387265ms, longest: 51.387265ms
[cache.typeCheckBatch.checkPackageForImport](http://localhost:8088/trace/cache.typeCheckBatch.checkPackageForImport) last: 42.661835ms, longest: 48.435984ms
[cache.typeCheckBatch.importPackage](http://localhost:8088/trace/cache.typeCheckBatch.importPackage) last: 41.938706ms, longest: 68.740203ms
[client/registerCapability](http://localhost:8088/trace/client/registerCapability) last: 459.571µs, longest: 5.792921ms
[completion.Completion](http://localhost:8088/trace/completion.Completion) last: 15.469948ms, longest: 148.626297ms
[gocommand.Runner.Run](http://localhost:8088/trace/gocommand.Runner.Run) last: 701.562809ms, longest: 737.707911ms
[gocommand.Runner.RunRaw](http://localhost:8088/trace/gocommand.Runner.RunRaw) last: 701.536021ms, longest: 2.007488733s
[golang.AllImportsFixes](http://localhost:8088/trace/golang.AllImportsFixes) last: 1.027123ms, longest: 83.470453ms
[golang.DocumentSymbols](http://localhost:8088/trace/golang.DocumentSymbols) last: 49.983µs, longest: 82.002µs
[golang.Format](http://localhost:8088/trace/golang.Format) last: 2.252323ms, longest: 2.252323ms
[golang.Highlight](http://localhost:8088/trace/golang.Highlight) last: 104.586µs, longest: 113.882µs
[golang.InlayHint](http://localhost:8088/trace/golang.InlayHint) last: 70.709µs, longest: 154.69582ms
[golang.SignatureHelp](http://localhost:8088/trace/golang.SignatureHelp) last: 15.479135ms, longest: 15.479135ms
[golang.computeTextEdits](http://localhost:8088/trace/golang.computeTextEdits) last: 15.805µs, longest: 15.805µs
[imports.FixImports](http://localhost:8088/trace/imports.FixImports) last: 837.706µs, longest: 1.023672ms
[initialize](http://localhost:8088/trace/initialize) last: 1.139349ms, longest: 1.139349ms
[initialized](http://localhost:8088/trace/initialized) last: 1.992974424s, longest: 1.992974424s
[lsp.Server.codeAction](http://localhost:8088/trace/lsp.Server.codeAction) last: 1.088372ms, longest: 540.596505ms
[lsp.Server.codeLens](http://localhost:8088/trace/lsp.Server.codeLens) last: 29.122µs, longest: 63.575µs
[lsp.Server.completion](http://localhost:8088/trace/lsp.Server.completion) last: 15.504095ms, longest: 148.650499ms
[lsp.Server.didChange](http://localhost:8088/trace/lsp.Server.didChange) last: 1.853364ms, longest: 1.603375327s
[lsp.Server.didChangeConfiguration](http://localhost:8088/trace/lsp.Server.didChangeConfiguration) last: 9.578416ms, longest: 12.507994ms
[lsp.Server.didChangeWatchedFiles](http://localhost:8088/trace/lsp.Server.didChangeWatchedFiles) last: 449.65µs, longest: 449.65µs
[lsp.Server.didOpen](http://localhost:8088/trace/lsp.Server.didOpen) last: 32.425992ms, longest: 34.723099ms
[lsp.Server.didSave](http://localhost:8088/trace/lsp.Server.didSave) last: 1.86014019s, longest: 1.86014019s
[lsp.Server.documentHighlight](http://localhost:8088/trace/lsp.Server.documentHighlight) last: 142.051µs, longest: 152.758µs
[lsp.Server.documentLink](http://localhost:8088/trace/lsp.Server.documentLink) last: 1.967647492s, longest: 1.967647492s
[lsp.Server.documentSymbol](http://localhost:8088/trace/lsp.Server.documentSymbol) last: 84.666µs, longest: 154.666µs
[lsp.Server.foldingRange](http://localhost:8088/trace/lsp.Server.foldingRange) last: 571.535µs, longest: 593.169µs
[lsp.Server.formatting](http://localhost:8088/trace/lsp.Server.formatting) last: 2.339969ms, longest: 2.339969ms
[lsp.Server.initialize](http://localhost:8088/trace/lsp.Server.initialize) last: 216.97µs, longest: 216.97µs
[lsp.Server.initialized](http://localhost:8088/trace/lsp.Server.initialized) last: 1.992896443s, longest: 1.992896443s
[lsp.Server.inlayHint](http://localhost:8088/trace/lsp.Server.inlayHint) last: 117.09µs, longest: 154.745629ms
[lsp.Server.signatureHelp](http://localhost:8088/trace/lsp.Server.signatureHelp) last: 15.517845ms, longest: 15.517845ms
[mod.Diagnostics](http://localhost:8088/trace/mod.Diagnostics) last: 717.283716ms, longest: 738.554354ms
[mod.UpgradeDiagnostics](http://localhost:8088/trace/mod.UpgradeDiagnostics) last: 8.462µs, longest: 30.292µs
[mod.VulnerabilityDiagnostics](http://localhost:8088/trace/mod.VulnerabilityDiagnostics) last: 1.661976764s, longest: 1.983652418s
[queued](http://localhost:8088/trace/queued) last: 1.456204894s, longest: 2.173209226s
[snapshot.Analyze](http://localhost:8088/trace/snapshot.Analyze) last: 111.145013ms, longest: 111.145013ms
[textDocument/codeAction](http://localhost:8088/trace/textDocument/codeAction) last: 2.054726172s, longest: 2.174585911s
[textDocument/codeLens](http://localhost:8088/trace/textDocument/codeLens) last: 1.456380668s, longest: 1.840501226s
[textDocument/completion](http://localhost:8088/trace/textDocument/completion) last: 17.61089ms, longest: 1.597640008s
[textDocument/didChange](http://localhost:8088/trace/textDocument/didChange) last: 2.059261ms, longest: 1.604931095s
[textDocument/didOpen](http://localhost:8088/trace/textDocument/didOpen) last: 2.058909667s, longest: 2.058909667s
[textDocument/didSave](http://localhost:8088/trace/textDocument/didSave) last: 1.860386423s, longest: 1.860386423s
[textDocument/documentHighlight](http://localhost:8088/trace/textDocument/documentHighlight) last: 17.774327ms, longest: 1.603916368s
[textDocument/documentLink](http://localhost:8088/trace/textDocument/documentLink) last: 2.16692516s, longest: 2.16692516s
[textDocument/documentSymbol](http://localhost:8088/trace/textDocument/documentSymbol) last: 309.556µs, longest: 2.008271693s
[textDocument/foldingRange](http://localhost:8088/trace/textDocument/foldingRange) last: 934.761µs, longest: 1.915687317s
[textDocument/formatting](http://localhost:8088/trace/textDocument/formatting) last: 2.692276ms, longest: 2.692276ms
[textDocument/inlayHint](http://localhost:8088/trace/textDocument/inlayHint) last: 436.26443ms, longest: 2.173335536s
[textDocument/publishDiagnostics](http://localhost:8088/trace/textDocument/publishDiagnostics) last: 72.321µs, longest: 1.004508ms
[textDocument/signatureHelp](http://localhost:8088/trace/textDocument/signatureHelp) last: 16.147943ms, longest: 16.147943ms
[window/logMessage](http://localhost:8088/trace/window/logMessage) last: 94.204µs, longest: 156.671µs
[window/workDoneProgress/create](http://localhost:8088/trace/window/workDoneProgress/create) last: 1.802205ms, longest: 1.802205ms
[work.Diagnostics](http://localhost:8088/trace/work.Diagnostics) last: 4.017µs, longest: 9.009µs
[workspace/configuration](http://localhost:8088/trace/workspace/configuration) last: 620.804µs, longest: 4.753181ms
[workspace/didChangeConfiguration](http://localhost:8088/trace/workspace/didChangeConfiguration) last: 1.985786238s, longest: 1.985786238s
[workspace/didChangeWatchedFiles](http://localhost:8088/trace/workspace/didChangeWatchedFiles) last: 1.558457114s, longest: 1.558457114s

@findleyr
Copy link
Contributor

@gordallott thanks, that's extremely useful.

Unfortunately, it confirms that there's something I really don't understand here, and which won't be fixed by the CL above: didChange, didOpen, and didSave should all be extremely fast operations, yet from your trace I can see that they are not.

Could you perhaps click on one and share the last and longest trace for lsp.Server.didSave, from the bottom half of that view? You may need to remove file paths from the trace (though I would like to know whether they are .go, go.mod, or go.work files).

I may also ask you to test with a new gopls CL that includes additional information.

@findleyr
Copy link
Contributor

@gordallott can you also visit http://localhost:8080/session/1?

How many Views do you have, and what are their IDs?
(Views are logical builds, and my theory is now that there is some bug causing you to churn through a lot of new Views)

gopherbot pushed a commit to golang/tools that referenced this issue Apr 10, 2024
With gopls@v0.15.0, zero config gopls made it much more likely that
sessions would have multiple Views. Additionally, with improved build
tag support, it made it more likely that these Views would share files.
As a result, we encountered (and fixed) this latent bug:

1. User changes file x.go, invalidating view A and B. A and B are
   scheduled for diagnosis.
2. User changes file y.go, invalidating only view B. Step (1) is
   cancelled and view B is scheduled for diagnosis.
3. View A never gets rediagnosed.

The fix was naive: just mark view A and B as dirty, and schedule a
goroutine to diagnose all dirty views after each step. As before, step
(2) would cancel the context from step (1).

But there's a problem: diagnoses were happening on the *Snapshot*
context, not the operation context. Therefore, if the goroutines of step
(1) and (2) both find the same snapshots, the diagnostics of step (1)
would *not* be cancelled, and would be performed in addition to the
diagnostics of (2). In other words, following a sequence of
invalidations, we could theoretically be collecting diagnostics N times
rather than 1 time.

In practice, this is not so much of a problem for smaller repositories.
Most of the time, changes are arriving at the speed of keystrokes, and
diagnostics are being scheduled faster than we can type. However, on
slower machines, or when there is more overall work being scheduled, or
when changes arrive simultaneously (such as with a 'save all' command or
branch switch), it is quite possible in practice to cause gopls to do
more work than necessary, including redundant loads. I'm not sure if
this is what conspires to cause the regressions described in
golang/go#66647, but it certainly is a real regression.

Fix this by threading the correct context into diagnoseSnapshot.
Additionally, add earlier context cancellation in a few cases where
redundant work was being performed despite a context cancellation.

For golang/go#66647

Change-Id: I67da1c186848286ca7b6221330a655d23820fd5d
Reviewed-on: https://go-review.googlesource.com/c/tools/+/577695
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
@gordallott
Copy link

@gordallott thanks, that's extremely useful.

Could you perhaps click on one and share the last and longest trace for lsp.Server.didSave, from the bottom half of that view? You may need to remove file paths from the trace (though I would like to know whether they are .go, go.mod, or go.work files).

Last

    19:34:06.884 end lsp.Server.didSave (+1.586964ms) URI=file:///home/gord/gordallott/<snip>/parser.go
        19:34:06.883 start cache.snapshot.clone
        19:34:06.883 end cache.snapshot.clone (+632.748µs)

Longest

    19:33:58.861 end lsp.Server.didSave (+1.83073071s) URI=file:///home/gord/gordallott/<snip>/parser.go
        19:33:58.860 start cache.snapshot.clone
        19:33:58.861 end cache.snapshot.clone (+390.505µs)

the file references just happen to be the file I had open at the time, same setup, tried to complete a symbol, tried to save, both slow. same deal if I am editing any file, the contents of the file doesn't seem to make any difference. (though using a different git repo, everything will be fast again)

I may also ask you to test with a new gopls CL that includes additional information.

is this go installable? the hash isn't as there's a replace directive that needs to be removed from the go.mod - i guess I could just build from source?

How many Views do you have, and what are their IDs?

Views

    ID: 5
    Type: GoModView
    Root: file:///home/gord/<path to repo>
    Folder: <workspacename>:file:///home/gord/<path to repo>

only one view, two overlays from the two files i have open

@findleyr
Copy link
Contributor

19:33:58.861 end lsp.Server.didSave (+1.83073071s) URI=file:///home/gord/gordallott//parser.go

Interesting that the file doesn't matter here. That's surprising, as for most files didSave should be extremely fast. It should be slow only if gopls thinks that build information may have changed (for example, because the file has a //go:build comment). And even then, it should stabilize.

is this go installable

If/when we need to test a fix or or debugging CL, I'll provide instructions for how to install it (indeed, because of the replace, you'll need to check out the commit and build from source).

only one view, two overlays from the two files i have open

I see the view ID is 5, which means it has recreated the view 5 times. If you do some slow operations, or try to use gopls for a minute, does the ID increment? That would explain why you keep seeing go list processes -- the view is being recreated.

I'm digging into the control flow, and pending your response to the question about the View ID I'll put together a CL with much more instrumentation to help us understand why state changes are taking so long.

Greatly appreciate your willingness to go back-and-forth here.

@gopherbot
Copy link

Change https://go.dev/cl/578036 mentions this issue: gopls: add instrumentation to debug golang/go#66647

@findleyr
Copy link
Contributor

@gordallott here's a one-liner to install the debugging CL above in #66647 (comment). Run it from a temp directory as it creates a "tools" subdirectory in which to shallow clone the CL and build gopls.

mkdir tools && cd tools && git init && git fetch --depth=1 https://go.googlesource.com/tools refs/changes/36/578036/1 && git checkout FETCH_HEAD && cd gopls && go install

Once you've done that, can you please redo the exercise above, where you perform some slow operations and then share the trace of the slowest lsp.Server.didSave operation listed at http://localhost:8080/trace/lsp.Server.didSave.

(also, still curious to hear whether the ID of the view at http://localhost:8080/session/1 keeps incrementing)

@gordallott
Copy link

okey doke, grabbed the above CL branch, latest info repeating the same thing (in a different file, different package, same repo)

view stuff

after restarting gopls, completing a symbol and saving

Views

    ID: 5
    Type: GoModView

after a few more completions and saving twice

Views

    ID: 11
    Type: GoModView

trace info

Trace Information
$/cancelRequest last: 102.896µs, longest: 104.904µs
$/progress last: 88.455µs, longest: 88.455µs
$/setTrace last: 1.811087272s, longest: 1.811115924s
Server.diagnose last: 2.015786458s, longest: 2.357447769s
Server.diagnoseChangedFiles last: 12.332066ms, longest: 247.881926ms
Server.diagnoseSnapshot last: 3.030459612s, longest: 3.383085766s
Server.publishDiagnostics last: 702.63µs, longest: 2.647408ms
cache.FetchGoEnv last: 6.648044ms, longest: 8.126277ms
cache.ModTidy last: 841.02227ms, longest: 1.04149448s
cache.ParseGoSrc last: 93.602µs, longest: 35.211023ms
cache.ParseMod last: 1.172056ms, longest: 1.172056ms
cache.Session.DidModifyFiles last: 587.895µs, longest: 2.021401254s
cache.Session.ExpandModificationsToDirectories last: 11.183µs, longest: 25.609µs
cache.Session.FileWatchingGlobPatterns last: 552.007µs, longest: 943.379µs
cache.Session.NewView last: 185.98µs, longest: 185.98µs
cache.Session.OrphanedFileDiagnostics last: 94.99µs, longest: 113.847µs
cache.Session.SnapshotOf last: 8.101µs, longest: 1.944446257s
cache.Session.createView last: 80.486µs, longest: 290.604µs
cache.Session.invalidateViewLocked last: 476.654µs, longest: 2.021322164s
cache.Session.viewOfLocked last: 3.359µs, longest: 58.272µs
cache.Snapshot.AwaitInitialized last: 2.825µs, longest: 2.141082242s
cache.defineView last: 65.337µs, longest: 88.125µs
cache.forEachPackage last: 793.957025ms, longest: 989.711383ms
cache.importsState.refreshProcessEnv last: 253.498189ms, longest: 1.08653179s
cache.importsState.runProcessEnvFunc last: 1.597429ms, longest: 123.08247ms
cache.readFile last: 49.708µs, longest: 2.025704ms
cache.resolveImportGraph last: 9.681973ms, longest: 227.659281ms
cache.sharedModCache.refreshDir last: 9.926362ms, longest: 457.52324ms
cache.snapshot.ModTidy last: 841.0648ms, longest: 1.049186974s
cache.snapshot.PackageDiagnostics last: 793.992045ms, longest: 989.751095ms
cache.snapshot.clone last: 463.977µs, longest: 36.813344ms
cache.snapshot.load last: 1.912954524s, longest: 2.139577317s
cache.typeCheckBatch.checkPackage last: 1.509433ms, longest: 181.499904ms
cache.typeCheckBatch.checkPackageForImport last: 446.560971ms, longest: 678.849964ms
cache.typeCheckBatch.importPackage last: 514.527563ms, longest: 666.052321ms
client/registerCapability last: 543.195µs, longest: 8.169472ms
completion.Completion last: 1.751337ms, longest: 138.671966ms
gocommand.Runner.Run last: 840.63555ms, longest: 1.040988297s
gocommand.Runner.RunRaw last: 840.611589ms, longest: 1.904049044s
golang.DocumentSymbols last: 94.577µs, longest: 150.091µs
golang.Format last: 3.228902ms, longest: 3.712472ms
golang.Highlight last: 60.693µs, longest: 32.037988ms
golang.InlayHint last: 320.505171ms, longest: 320.505171ms
golang.SignatureHelp last: 44.365µs, longest: 308.976µs
golang.allImportsFixes last: 1.605309ms, longest: 1.712399ms
golang.computeTextEdits last: 16.223µs, longest: 16.223µs
imports.FixImports last: 1.494453ms, longest: 1.535768ms
initialize last: 1.374226ms, longest: 1.374226ms
initialized last: 2.16461796s, longest: 2.16461796s
lsp.Server.addFolders last: 2.163948884s, longest: 2.163948884s
lsp.Server.codeAction last: 1.667696ms, longest: 2.064599161s
lsp.Server.codeLens last: 92.986µs, longest: 109.301µs
lsp.Server.completion last: 1.820558ms, longest: 138.774957ms
lsp.Server.didChange last: 2.36282ms, longest: 2.022315824s
lsp.Server.didChangeConfiguration last: 8.316619ms, longest: 13.090024ms
lsp.Server.didChangeWatchedFiles last: 1.267497ms, longest: 1.463139ms
lsp.Server.didOpen last: 37.784145ms, longest: 37.784145ms
lsp.Server.didSave last: 1.329762ms, longest: 1.711276884s
lsp.Server.documentHighlight last: 119.118µs, longest: 32.094651ms
lsp.Server.documentLink last: 1.932978592s, longest: 1.964821574s
lsp.Server.documentSymbol last: 146.425µs, longest: 216.393µs
lsp.Server.foldingRange last: 788.352µs, longest: 1.197737ms
lsp.Server.formatting last: 3.30479ms, longest: 3.754472ms
lsp.Server.handleOptionResults last: 6.06µs, longest: 19.283µs
lsp.Server.initialize last: 258.955µs, longest: 258.955µs
lsp.Server.initialized last: 2.164544743s, longest: 2.164544743s
lsp.Server.inlayHint last: 320.546227ms, longest: 320.546227ms
lsp.Server.newFolder last: 7.239027ms, longest: 10.108836ms
lsp.Server.signatureHelp last: 77.158µs, longest: 344.772µs
lsp.Server.warnAboutModifyingGeneratedFiles last: 7.809µs, longest: 40.917µs
lsp.server.updateWatchedDirectories last: 634.4µs, longest: 9.479341ms
mod.Diagnostics last: 841.116913ms, longest: 1.049281256s
mod.UpgradeDiagnostics last: 10.051µs, longest: 31.132µs
mod.VulnerabilityDiagnostics last: 1.165084539s, longest: 2.150643768s
queued last: 16.465µs, longest: 2.368044248s
snapshot.Analyze last: 352.408782ms, longest: 519.204331ms
textDocument/codeAction last: 1.918291346s, longest: 2.368059846s
textDocument/codeLens last: 271.644µs, longest: 1.994976808s
textDocument/completion last: 30.81277ms, longest: 2.022593328s
textDocument/didChange last: 2.54601ms, longest: 2.022574267s
textDocument/didOpen last: 38.151349ms, longest: 2.226087915s
textDocument/didSave last: 1.466477ms, longest: 1.711427347s
textDocument/documentHighlight last: 321.885µs, longest: 2.022597715s
textDocument/documentLink last: 3.647226089s, longest: 3.647226089s
textDocument/documentSymbol last: 478.917µs, longest: 2.221238156s
textDocument/foldingRange last: 1.210711ms, longest: 2.070133853s
textDocument/formatting last: 1.940936524s, longest: 1.971913023s
textDocument/inlayHint last: 1.962431539s, longest: 2.368180993s
textDocument/publishDiagnostics last: 68.199µs, longest: 783.94µs
textDocument/signatureHelp last: 267.275µs, longest: 709.983µs
window/logMessage last: 108.668µs, longest: 173.38µs
window/workDoneProgress/create last: 2.610363ms, longest: 2.610363ms
work.Diagnostics last: 4.95µs, longest: 9.969µs
workspace/configuration last: 537.527µs, longest: 4.505278ms
workspace/didChangeConfiguration last: 1.819317265s, longest: 1.819317265s
workspace/didChangeWatchedFiles last: 1.444003ms, longest: 1.441871345s

lsp.Server.didSave spans

lsp.Server.didSave
Last

    09:41:05.077 end lsp.Server.didSave (+1.329762ms) URI=file:///home/gord/<snip>/cache.go
        09:41:05.076 start cache.Session.ExpandModificationsToDirectories
        09:41:05.076 end cache.Session.ExpandModificationsToDirectories (+16.265µs)
        09:41:05.076 start cache.Session.DidModifyFiles
        09:41:05.076 end cache.Session.DidModifyFiles (+500.334µs)
            09:41:05.076 event (+225.391µs) message="done checking views" 
            09:41:05.076 start cache.Session.viewOfLocked URI=file:///home/gord/<snip>/cache.go
            09:41:05.076 end cache.Session.viewOfLocked (+4.934µs) URI=file:///home/gord/<snip>/cache.go
            09:41:05.076 start cache.Session.invalidateViewLocked
            09:41:05.076 start window/logMessage method="window/logMessage" direction="out"
            09:41:05.076 end window/logMessage (+74.353µs) method="window/logMessage" direction="out"
                09:41:05.076 event (+454.293µs) label= status.code="OK" 
            09:41:05.076 end cache.Session.invalidateViewLocked (+445.327µs)
                09:41:05.076 start cache.Snapshot.AwaitInitialized
                09:41:05.076 end cache.Snapshot.AwaitInitialized (+4.517µs)
                09:41:05.076 start cache.snapshot.clone
                09:41:05.076 end cache.snapshot.clone (+419.32µs)
        09:41:05.076 start lsp.server.updateWatchedDirectories
        09:41:05.077 start Server.diagnoseSnapshot snapshot=1 directory=file:///home/gord/gordallott/axiom
        09:41:05.077 end lsp.server.updateWatchedDirectories (+764.333µs)
            09:41:05.076 start cache.Session.FileWatchingGlobPatterns
            09:41:05.077 end cache.Session.FileWatchingGlobPatterns (+677.585µs)
        09:41:05.381 end Server.diagnoseSnapshot (+304.344574ms) snapshot=1 directory=file:///home/gord/gordallott/axiom
            09:41:05.097 start Server.diagnoseChangedFiles snapshot=1 directory=file:///home/gord/gordallott/axiom
            09:41:05.345 end Server.diagnoseChangedFiles (+247.881926ms) snapshot=1 directory=file:///home/gord/gordallott/axiom
                09:41:05.097 start cache.snapshot.PackageDiagnostics
                09:41:05.345 end cache.snapshot.PackageDiagnostics (+247.819518ms)
                    09:41:05.097 start cache.forEachPackage packages=1
                    09:41:05.345 end cache.forEachPackage (+247.75911ms) packages=1
            09:41:05.345 start Server.publishDiagnostics
            09:41:05.345 end Server.publishDiagnostics (+255.109µs)
                09:41:05.345 start textDocument/publishDiagnostics method="textDocument/publishDiagnostics" direction="out"
                09:41:05.345 end textDocument/publishDiagnostics (+77.244µs) method="textDocument/publishDiagnostics" direction="out"
                    09:41:05.345 event (+0s) label= status.code="OK" 

Longest

    09:40:52.108 end lsp.Server.didSave (+1.711276884s) URI=file:///home/gord/<snip>/cache.go
        09:40:50.396 start cache.Session.ExpandModificationsToDirectories
        09:40:50.396 end cache.Session.ExpandModificationsToDirectories (+8.601µs)
        09:40:50.396 start cache.Session.DidModifyFiles
        09:40:52.107 end cache.Session.DidModifyFiles (+1.710759477s)
            09:40:50.396 event (+205.018µs) message="done checking views" 
            09:40:50.396 start cache.Session.viewOfLocked URI=file:///home/gord/<snip>/cache.go
            09:40:50.396 end cache.Session.viewOfLocked (+13.129µs) URI=file:///home/gord/<snip>/cache.go
            09:40:50.396 start cache.Session.invalidateViewLocked
            09:40:50.396 start window/logMessage method="window/logMessage" direction="out"
            09:40:50.396 end window/logMessage (+50.789µs) method="window/logMessage" direction="out"
                09:40:50.396 event (+289.865µs) label= status.code="OK" 
            09:40:52.107 end cache.Session.invalidateViewLocked (+1.710703453s)
                09:40:50.396 start cache.Snapshot.AwaitInitialized
                09:40:52.107 end cache.Snapshot.AwaitInitialized (+1.710293701s)
                09:40:52.107 start cache.snapshot.clone
                09:40:52.107 end cache.snapshot.clone (+397.023µs)
        09:40:52.107 start lsp.server.updateWatchedDirectories
        09:40:52.107 start Server.diagnoseSnapshot snapshot=1 directory=file:///home/gord/gordallott/axiom
        09:40:52.108 end lsp.server.updateWatchedDirectories (+471.534µs)
            09:40:52.107 start cache.Session.FileWatchingGlobPatterns
            09:40:52.107 end cache.Session.FileWatchingGlobPatterns (+357.458µs)
        09:40:52.108 end Server.diagnoseSnapshot (+964.74µs) snapshot=1 directory=file:///home/gord/gordallott/axiom

@findleyr
Copy link
Contributor

@gordallott it looks like the slowness is caused by reinitializing your build over and over. That would perfectly explain the symptoms you observe.

I noticed that gopls had received at least two didChangeConfiguration notifications from VS Code, because of the line below (last != longest).

lsp.Server.didChangeConfiguration last: 8.316619ms, longest: 13.090024ms

This stands out to me. In my sessions, I get no didChangeConfiguration notifications, and would expect at most one. In gopls@v0.15.0+, any change to configuration causes a reinitialization--this was a vast simplification, and was assumed not to be a significant performance hit since configuration changes should be infrequent.

If you start gopls with -rpc.trace (as described here) and look at gopls (server) in the output panel, do you see a lot of didChangeConfiguration RPCs? (you can just ctrl-f search for the string "didChangeConfiguration".

If you do, then we are very close to a root cause: there is some process that causes VS Code to send repeated didChangeConfiguration notifications, and gopls@v0.14.2 detects these as "minor" changes, whereas gopls@v0.15.0 assumes that any configuration change could affect state and reinitializes the build. The fix is probably for gopls to be smarter and detect when configuration has not changed, and/or get VS Code to stop sending didChangeConfiguration notifications!

If you don't see a lot of didChangeConfiguration notifications, then it's back to the drawing board (I have a few other ideas that we can narrow down).

@gopherbot
Copy link

Change https://go.dev/cl/578037 mentions this issue: gopls/internal/server: don't reset views if configuration did not change

@gordallott
Copy link

looks like a fair amount, just going to dump the lines (w/timestamps) that it's found in my output

[Trace - 19:25:24.643 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:25:30.724 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:25:50.041 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:25:55.189 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:26:06.171 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:26:07.630 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:26:08.004 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:26:15.662 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:26:15.916 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:26:17.472 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:26:17.784 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:26:53.246 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:05.517 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:05.843 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:09.430 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:10.159 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:10.568 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:13.518 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:15.613 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:16.414 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:17.253 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:18.110 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:18.455 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:23.880 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:25.059 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:25.529 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:25.871 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:26.414 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:27.746 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:28.220 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:28.626 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:28.965 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:29.464 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:29.880 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:30.306 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:30.756 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:35.998 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:37.645 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:38.077 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:38.738 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:39.166 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:27:40.187 PM] Sending notification 'workspace/didChangeConfiguration'.
[Trace - 19:28:55.903 PM] Sending notification 'workspace/didChangeConfiguration'.

also want to note that prior to this issue I already tried the standard unload all my extensions other than go techniques. so it's unlikely that any other extensions might be causing this - just having the go extension enabled by itself is enough

@adonovan
Copy link
Member

Thanks! This is very helpful. @findleyr tells me the CL above should be a fix for this issue.

We should also report a VS Code bug that it is sending spurious config change notifications.

@findleyr
Copy link
Contributor

Hi @gordallott, @zhangfannie, and @hitzhangjie, I'd be very curious to know whether the CL referenced below fixes the performance regression for you. This CL prevents gopls from reinitializing if configuration did not actually change following a didChangeConfiguration notification.

This one liner should be run from a temp directory, and installs gopls with the proposed fix. (It shallow clones gopls at the correct commit and installs from source).

mkdir tools && cd tools && git init && git fetch --depth=1 https://go.googlesource.com/tools refs/changes/37/578037/3 && git checkout FETCH_HEAD && cd gopls && go install

@gordallott the change notifications in #66647 (comment) look like a VS Code or VS Code Go bug (CC @hyangah). VS Code should not be sending repeated didChangeConfiguration notifications. I wonder if this is an artifact of your setup somehow.

@findleyr
Copy link
Contributor

Gentle ping: I believe the CL in #66647 (comment) should fix the regression in v0.15.0+. If it does, I'd like to cherry-pick it into a prerelease today, to be released next week.

If it doesn't fix it, then perhaps configuration is actually changing in a meaningful way, which gopls@v0.14.2 would tolerate. That would be another source of curiosity.

@gordallott
Copy link

Can confirm that the above CL fixes the issue (or at least, is as perceptually fast as 1.14 is), excellent stuff

gopherbot pushed a commit to golang/tools that referenced this issue Apr 12, 2024
In CL 538796, options were made immutable on the View, meaning any
change to options required a new View. As a result, the
minorOptionsChange heuristic, which avoided recreating views on certain
options changes, was removed.

Unfortunately, in golang/go#66647, it appears that certain clients may
send frequent didChangeConfiguration notifications. Presumably the
configuration is unchanged, and yet gopls still reinitializes the view.
This may be a cause of significant performance regression for these
clients.

Fix this by making didChangeConfiguration a no op if nothing changed,
using reflect.DeepEqual to compare Options. Since Hooks are not
comparable due to the GofumptFormat func value, they are excluded from
comparison. A subsequent CL will remove hooks altogether.

For golang/go#66647

Change-Id: I280059953d6b128461bef1001da3034f89ba3226
Reviewed-on: https://go-review.googlesource.com/c/tools/+/578037
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Auto-Submit: Robert Findley <rfindley@google.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
@gopherbot
Copy link

Change https://go.dev/cl/578040 mentions this issue: [gopls-release-branch.0.15] gopls/internal/server: don't reset views if configuration did not change

gopherbot pushed a commit to golang/tools that referenced this issue Apr 12, 2024
…if configuration did not change

In CL 538796, options were made immutable on the View, meaning any
change to options required a new View. As a result, the
minorOptionsChange heuristic, which avoided recreating views on certain
options changes, was removed.

Unfortunately, in golang/go#66647, it appears that certain clients may
send frequent didChangeConfiguration notifications. Presumably the
configuration is unchanged, and yet gopls still reinitializes the view.
This may be a cause of significant performance regression for these
clients.

Fix this by making didChangeConfiguration a no op if nothing changed,
using reflect.DeepEqual to compare Options. Since Hooks are not
comparable due to the GofumptFormat func value, they are excluded from
comparison. A subsequent CL will remove hooks altogether.

For golang/go#66647
Updates golang/go#66730

Change-Id: I280059953d6b128461bef1001da3034f89ba3226
Reviewed-on: https://go-review.googlesource.com/c/tools/+/578037
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Auto-Submit: Robert Findley <rfindley@google.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
(cherry picked from commit e388fff)
Reviewed-on: https://go-review.googlesource.com/c/tools/+/578040
@findleyr
Copy link
Contributor

That's fantastic to hear. I suspect this was affecting a number of users. Really appreciate you going the extra mile to follow up, @gordallott.

I've cut a prerelease with the fix (among others). Would be great if you confirm that it still fixes the problem for you:

go install golang.org/x/tools/gopls@v0.15.3-pre.2

@zhangfannie @hitzhangjie I'd also be very interested if this fixes your problems as well.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
gopls/performance Issues related to gopls performance (CPU, memory, etc). gopls Issues related to the Go language server, gopls. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

7 participants