Dart LSP slow startup/first response on large codebase

[RobertBrunhage]

Dart SDK version: 3.0.6 (stable) (Tue Jul 11 18:49:07 2023 +0000) on "macos_arm64"

LSP takes a long time before LSP actions work

Not sure how to debug this so if you have tips/approaches, please let me know!

In short, when I open a project with Neovim the dartls LSP starts and in a large project takes towards half a minute for anything related to the LSP to work (hover docs, code completion, code actions etc).

Below I added duration for dart analyze with time dart analyze with a small project and large project to see the difference. Not sure if this command is even helpful in debugging but at least it shows the difference I experience.

Small project

real    0.65s
user    0.48s
sys     0.35s
cpu     127%

Large project

real    31.19s
user    33.99s
sys     8.12s
cpu     135%

---

The large project contains, internal packages and is in general very large (>690k LOC counted with find . -name '*.dart' | xargs wc -l), but I would still expect it to be faster than 30 seconds for anything to work, and the subsequent action takes ~half the time of that (18 seconds). After those two (first 30 sec wait for a LSP action, and then 18 sec, it becomes almost instant).

Again, if there are better ways to debug this, please let me know.

I will add this here as well as that is where I got the config from (mine is a bit leaner as I don't use outline etc.
https://github.com/neovim/nvim-lspconfig/blob/master/lua/lspconfig/server_configurations/dartls.lua

---

Tweet referencing this issue -> https://twitter.com/RobertBrunhage/status/1680840204309913600

[bwilkerson]

@DanTup

[DanTup]

Below I added duration for dart analyze

Do you mean it takes the same time (~30s) for both dart analyze and via the LSP server, or that the LSP server takes ~30s but dart analyze is faster?

If you start the server with --instrumentation-log-file=/path/to/log.txt it'll produce a log with timestamps that might help understand what's happening during that period (note: the log will likely contain parts of your source code but if you can't share that might be able to use the timestamps at the start of the lines to see where the time is going).

[RobertBrunhage]

Below I added duration for dart analyze

Do you mean it takes the same time (~30s) for both dart analyze and via the LSP server, or that the LSP server takes ~30s but dart analyze is faster?

dart analyze was just there to have some kind of benchmark for something, and it did showcase about the difference in the perceived LSP speed. In this case I just counted the seconds when I was trying to do code actions with the LSP and I just happened to use the dart analyze to do some kind of benchmark for the speed in general (might have been unrelated)

If you start the server with --instrumentation-log-file=/path/to/log.txt it'll produce a log with timestamps that might help understand what's happening during that period (note: the log will likely contain parts of your source code but if you can't share that might be able to use the timestamps at the start of the lines to see where the time is going).

Got a log now and the first thing I see is the initial request starts at 1689575376779 and the remaining files starts to analyze at 1689575389867, which is 13 seconds

1689575376763:Ver:1638536083352700528870:unknown.client.lsp:unknown:1.34.0:3.0.0
1689575376779:
1689575376831:
1689575376834:Req:{} // this requested the whole file it seems when I tried to check the hover docs of a class
1689575376880:Res:{"id"::4,"jsonrpc"::"2.0","method"::"client/registerCapability","params"::{"registrations"::[{"id"::"0","method"::"textDocument/hover","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"}]}},{"id"::"1","method"::"textDocument/formatting","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"}]}},{"id"::"2","method"::"textDocument/rangeFormatting","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"}]}},{"id"::"3","method"::"textDocument/definition","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"}]}},{"id"::"4","method"::"textDocument/codeAction","registerOptions"::{"codeActionKinds"::["source","source.organizeImports","source.fixAll","source.sortMembers","quickfix","refactor"],"documentSelector"::[{"language"::"dart","scheme"::"file"}]}},{"id"::"5","method"::"textDocument/rename","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"}],"prepareProvider"::true}},{"id"::"6","method"::"textDocument/inlayHint","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"}],"resolveProvider"::false}}]}}
1689575376880:Req:{"result"::[{"analysisExcludedFolders"::["\/Users\/robertbrunhage\/AppData\/Local\/Pub\/Cache","\/Users\/robertbrunhage\/.pub-cache","\/opt\/homebrew\/","\/Users\/robertbrunhage\/tools\/flutter\/"],"updateImportsOnRename"::true,"completeFunctionCalls"::true,"showTodos"::true}],"jsonrpc"::"2.0","id"::3}
1689575376881:Req:{"result"::null,"jsonrpc"::"2.0","id"::4}
1689575389867:Res:{"jsonrpc"::"2.0","method"::"textDocument/publishDiagnostics","params"::{"diagnostics"::[],"uri"::"file::///Users/robertbrunhage/work/something/android/app/src/profile/AndroidManifest.xml"}}

This one was 3 seconds (does it really need to analyze the xml files?)

1689575390506:Res:{"jsonrpc"::"2.0","method"::"textDocument/publishDiagnostics","params"::{"diagnostics"::[],"uri"::"file::///Users/robertbrunhage/work/something/build/firebase_analytics/intermediates/aapt_friendly_merged_manifests/debug/aapt/AndroidManifest.xml"}}
1689575393482:Res:{"jsonrpc"::"2.0","method"::"textDocument/publishDiagnostics","params"::{"diagnostics"::[],"uri"::"file::///Users/robertbrunhage/work/something/build/some_plugin/intermediates/merged_manifest/debug/AndroidManifest.xml"}}

Another one that took a couple of seconds

1689575394397:Res:{"jsonrpc"::"2.0","method"::"textDocument/publishDiagnostics","params"::{"diagnostics"::[],"uri"::"file::///Users/robertbrunhage/work/something/packages/something_package/pubspec.yaml"}}
1689575396449:Res:{"id"::5,"jsonrpc"::"2.0","method"::"window/workDoneProgress/create","params"::{"token"::"ANALYZING"}}
1689575397093:Res:{"jsonrpc"::"2.0","method"::"textDocument/publishDiagnostics","params"::{"diagnostics"::[],"uri"::"file::///Users/robertbrunhage/work/something/lib/main.dart"}}
1689575397096:Res:{//removed}
1689575397097:Req:{//removed}
1689575397172:Req:{"result"::null,"jsonrpc"::"2.0","id"::5}
1689575397173:Res:{"jsonrpc"::"2.0","method"::"$/progress","params"::{"token"::"ANALYZING","value"::{"kind"::"begin","title"::"Analyzing…"}}}

In the end I can see the following which is also >10 sec (note that above is a similar line but that happened in the middle of the log)

1689575399907:Res:{"jsonrpc"::"2.0","method"::"$/progress","params"::{"token"::"ANALYZING","value"::{"kind"::"end"}}}
1689575412971:Req:{"id"::4,"jsonrpc"::"2.0","method"::"shutdown"}
1689575412972:Res:{"id"::4,"jsonrpc"::"2.0","result"::null}
1689575412995:Req:{"jsonrpc"::"2.0","method"::"exit"}

[DanTup]

dart analyze was just there to have some kind of benchmark for something, and it did showcase about the difference in the perceived LSP speed

Sorry, it's still not clear to me whether dart analyze is also taking around the same amount of time, or whether the issue is specific to going through the LSP server. It's expected that the LSP server will be slower to respond during startup and initial analysis, so if the delay you see roughly matches the time taken to run dart analyze in the same folder, that's probably expected.

Got a log now and the first thing I see is the initial request starts at 1689575376779 and the remaining files starts to analyze at 1689575389867, which is 13 seconds

The time prior to the first publishDiagnostics includes discovery of all of the projects (which includes walking down the whole open directory looking for pubspec.yamls). Can you confirm whether the folder that is being set as the workspace root is the folder you expect, or if it's something much larger (such as your home directory)? The directory will be in the line that contains "method"::"initialize" and could be either rootPath, rootUri or workspaceFolders.

One thing that would probably speed things up at the expensive of only analyzing a subset of projects is setting onlyAnalyzeProjectsWithOpenFiles. Usually the server will analyze the entire folder that the client gives to it, but with this option it will only look for projects related to open files.

[RobertBrunhage]

Sorry, it's still not clear to me whether dart analyze is also taking around the same amount of time, or whether the issue is specific to going through the LSP server. It's expected that the LSP server will be slower to respond during startup and initial analysis, so if the delay you see roughly matches the time taken to run dart analyze in the same folder, that's probably expected.

I would say it roughly matches the time of dart analyze. So in a small/new project the LSP and dart analyze is pretty much instant <1 sec. On large projects it's >30s for both LSP commands (the first one) and dart analyze. Does that clarify?

Can you confirm whether the folder that is being set as the workspace root is the folder you expect

This matches the project's folder path (copy pasted and removing the project name: "rootPath"::"\/Users\/robertbrunhage\/work\/something)

One thing that would probably speed things up at the expensive of only analyzing a subset of projects is setting onlyAnalyzeProjectsWithOpenFiles. Usually the server will analyze the entire folder that the client gives to it, but with this option it will only look for projects related to open files.

I can already see (and did this to try and speed things up) that I am using onlyAnalyzeProjectsWithOpenFiles

"onlyAnalyzeProjectsWithOpenFiles"::true,"outline"::false,"flutterOutline"::false

---

I also noticed that after this initial LSP analyzing and the first LSP action takes place I would expect all the subsequent requests to be fast, but I find that sometimes the 2nd and 3rd requests are also slow (not 30 sec slow but more around 10 sec slow), might be another topic though but wanted to bring it up anyway :)

[DanTup]

Thanks for the clarification. It sounds like the issue is just that initial analysis takes longer than you'd expect. Without a concrete project to test with, it's hard to say whether the times you're seeing are normal or not.

I'm surprised that onlyAnalyzerProjectsWithOpenFiles didn't make a difference though (unless you had files open that touched every project). If you run the server with --port=8123 and then open http://localhost:8123/ so you see a different number of contexts created with this setting? You should see 0 contexts with no open files, or 1 for each project you have an open file from.

On the left here I had an open workspace with 6 projects, then when I enabled onlyAnalyzeProjectsWithOpenFiles and restarted, only the project for the open file produced a context.

If your workspace has a large number of projects and you're not opening files from many of them, I would expect this to make a noticeable difference.

[RobertBrunhage]

@DanTup I did the same and is stating 14 contexts. All those are local packages, I always just open the entire project and not some folder containing other projects.

here was also another look at the timings (learned something new)

[DanTup]

I did the same and is stating 14 contexts

What files did you have open? You shouldn't see lots of contexts when using onlyAnalyzeProjectsWithOpenFiles if you don't have files open from 14 projects.

For example, if I open the pkg folder in the SDK with onlyAnalyzeProjectsWithOpenFiles=false then I see 5contexts. If I setonlyAnalyzeProjectsWithOpenFiles=trueand open the same folder, I see 0 contexts. If I open a file (for exampleanalysis_server\lib\src\lsp\lsp_analysis_server.dart`) then I see a single context.

Can you confirm whether you're seeing 14 contexts with no/one open file, or if you had many files open? If you had zero/one files open, are you able to verify in the log that onlyAnalyzeProjectsWithOpenFiles is still true, and how many textDocument.didOpen lines are logged (to ensure the open files the server is told about match what you're expecting)?

Thanks!

[joeldegerman99]

@RobertBrunhage @DanTup I have the same issue where I work. We have around 2.3k files and the analyze and lsp is super slow. I do not have any statistics but if requested I could get some if you want some more data to look at?

[DanTup]

@joeldegerman99 it would be interesting to know:

• how many contexts you have (see above)
• how long is "super slow"
• whether this is mainly after you've pulled significant changes to the project or upgraded SDK, or is it also slow if you just run Developer: Reload Window in VS Code (eg. everything is fully cached)
• whether you're using onlyAnalyzeProjectsWithOpenFiles (I don't really recommend using this setting - it trades some performance at startup for performance when opening/closing files, but it would be useful to know whether you enabled it)

[Reprevise]

@DanTup I have a pretty large Flutter project. It takes ~30 seconds (as seen in the timings) to actually start writing Dart with an active LSP. I only have 1 context, and I use whatever the default is for onlyAnalyzeProjectsWithOpenFiles.

Also is it a known issue that the "Analyzer Additional Args" setting doesn't get applied when the Reload Window command is triggered?

[DanTup]

@Reprevise 30s does sound pretty slow to me - does this reproduce after a restart (eg. with no code changes or SDK change)? For comparison, when I open my analysis server workspace, I see:

• 9 contexts
• 3,000 Dart files
• 2.5s for the initialized notification handling

Can you reproduce this on a public project? An instrumentation log may help, but it can contain parts of your source files so is best collected with a public project.

Also is it a known issue that the "Analyzer Additional Args" setting doesn't get applied when the Reload Window command is triggered?

Nope, it's definitely not :) That command actually tears down the whole extension host and restarts it, so it's not clear to me how Reload Window would behave differently to something like just restarting VS Code. If you enable the analysis server log it should record exactly what arguments it's starting the server with. If you think it's not working right, please file an issue at https://github.com/Dart-Code/Dart-Code/issues/new/choose with details. Thanks!