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鈥檒l occasionally send you account related emails.

Already on GitHub? Sign in to your account

Ctrl+Click on a symbol outside of your workspace is very slow #2873

Closed
RaviKavaiya opened this issue Oct 13, 2020 · 19 comments
Closed

Ctrl+Click on a symbol outside of your workspace is very slow #2873

RaviKavaiya opened this issue Oct 13, 2020 · 19 comments
Labels
in editor Relates to code editing or language features is bug
Milestone

Comments

@RaviKavaiya
Copy link

RaviKavaiya commented Oct 13, 2020

Describe the bug
Hi @DanTup 馃憢
I am facing really slow plugin behaviour (Dart and Flutter). Generally, each and every action seems to be very slow.
I don't remember from when all this started, but maybe since last 4-5 releases, I am facing this issue.

Things which are slow for me:

To Reproduce
Steps to reproduce the behavior:

  1. Enable LSP
  2. Do above things

Expected behavior
In non-LSP, it is instant. But in LSP mode, it is very much problematic.

Versions (please complete the following information):

  • VS Code version: 1.50.0
  • Dart extension version: 3.15.0
  • Dart/Flutter SDK version: Flutter 1.22.0 鈥 channel stable
@DanTup
Copy link
Member

DanTup commented Oct 13, 2020

Does this happen every time you do the action, or only the first time for each session?

Could you try enabling the Analysis server instrumentation log and reproduce the issue, then provide the log? (be sure to turn the logging off afterwards, as it can generate quite large files over long sessions).

Please invoke Go-to-Definition on the same thing multiple times while reproducing, so they're all captured in the log.

Thanks!

@DanTup DanTup added the awaiting info Requires more information from the customer to progress label Oct 13, 2020
@RaviKavaiya
Copy link
Author

Okay, will do that and report you

@RaviKavaiya
Copy link
Author

@DanTup

Does this happen every time you do the action, or only the first time for each session?

  • Difficult to tell. Sometimes, the Go-to definition is super-instant. Sometimes, it is slow even if done repeatedly.

The problem here is, this issue mostly (99%) happens with larger projects (around >150KB pure dart source), and it doesn't happen at all (but happens very rarely) in the sample Flutter app (flutter create something)

A side note:

  • Symbol renaming is still slow even in non-LSP mode (but with large projects only)

@DanTup
Copy link
Member

DanTup commented Oct 13, 2020

The slow renaming is being tracked in #2231, though I'm not sure if the slow Go-to-Definition is related (I initially thought so, but if that's happening only in LSP then it might be different).

@RaviKavaiya
Copy link
Author

Oh I see. This issue I am facing is bit more frustrating. One strange thing I found when Go-to definition is, if the file which contains the definition is already open, it does this instant (project size doesn't matter here).
But if the file is not open in editor, we get this slowness issue.

So, my primary assumption is that the analyzer does some heavy work while searching for definition.

@RaviKavaiya
Copy link
Author

EDIT: One more performance related issue.

  • The code actions. I don't know exactly what it is, but actions like (wrap with container, wrap with widget, remove widget) are also slow on LSP mode.

@DanTup
Copy link
Member

DanTup commented Oct 13, 2020

This all does sound a lot like the other issue - which is that the index for those files is not built until the requests are made, and therefore it's slow. I'll keep this issue open, but may fold it into #2231 depending on what I find.

@DanTup DanTup added in editor Relates to code editing or language features and removed awaiting info Requires more information from the customer to progress labels Oct 13, 2020
@DanTup DanTup added this to the v3.16.0 milestone Oct 13, 2020
@RaviKavaiya
Copy link
Author

I agree on your assumption. The last issue I told (actions like wrap widget) are also taking 3-4 seconds to appear on non-LSP mode for the first time. After that, they are instant.

But in LSP, it takes around 5 seconds every time. So yes, this has definitely something to do regarding loading of these things.

@DanTup
Copy link
Member

DanTup commented Oct 14, 2020

How reliably can you reproduce the issue shown in the video above? Are there any files in your project other than those two? I'm trying with LSP and Dart SDK 2.10.0 but it's always instant. I tried with/without a pubspec, and with test1.dart open at startup, or closed. Cmd+Clicking always instantly jumps to test2.dart (it was not previously open).

If you can capture a log (see #2873 (comment)) while that happens, being able to repro here may help.

(If these files exist in another larger project, can you confirm if it only happens within the first few minutes of opening the project, or also after it's been open for a while?)

@DanTup DanTup added the awaiting info Requires more information from the customer to progress label Oct 14, 2020
@RaviKavaiya
Copy link
Author

Ok @DanTup . In my video, the files were not alone. There were many files.

This happens even after I am working on the same project for 3 hours.

I will try to create a sample project (which is big enough to reproduce this) and post here the logs (as I came to know that logging also logs whole file content).

@RaviKavaiya
Copy link
Author

RaviKavaiya commented Oct 14, 2020

@DanTup Here's a sample debug file.

Steps:

  1. I opened the project.
  2. Waited for analysis to complete.
  3. Again waited for around 10 seconds.
  4. Only main.dart file was opened initially.
  5. In main(), I clicked on a class name (Invoked Go-to), that took around 5-6 seconds to show.
  6. Close the opened file.
  7. Repeated the steps (5,6) again 2 times (clicked same symbol) (same delay experienced).

Let me know if you need any more info.
(Note: I had no time to create a new and big project. So, this is my live project)

dbg_goto.txt

EDIT:

  • I use fvm. Is this issue has anything to do with this??

@DanTup
Copy link
Member

DanTup commented Oct 26, 2020

Thanks for the log! All of the definition calls I checked were less than a second, but there are some things I wouldn't expect in there (like a lot of requests immediately cancelled, and a fairly long 6-second analysis stint after jumping to a file in the pubspec).

I'll do some more testing here and see what I can find. Thanks!

@DanTup DanTup removed the awaiting info Requires more information from the customer to progress label Oct 26, 2020
@DanTup
Copy link
Member

DanTup commented Oct 27, 2020

I did some testing of this, and realised the analysis was correct - when you jump to a file in the pubcache, it triggers an analysis of that file (which may involve reading other files that are imported). It didn't take 6 seconds for me (only 2), though I don't think that should have a big impact on the definition speed.

So I extracted all of the textDocument/definition requests in the log to see which ones are the slowest. There are quire a few, because VS Code will often ask for some definitions when other things occur (for example hovering over a symbol and pressing Ctrl/Command will trigger a definition request even if you don't click).

1602684685541:Req:{"jsonrpc"::"2.0","id"::3,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/main.dart"},"position"::{"line"::32,"character"::9}}}
1602684685577:Res:{"id"::3,"jsonrpc"::"2.0","result"::[{"originSelectionRange"::{"start"::{"line"::32,"character"::7},"end"::{"line"::32,"character"::15}},"targetUri"::"file::///Users/rvk/.pub-cache/hosted/pub.dartlang.org/bloc-6.0.3/lib/src/bloc.dart","targetRange"::{"start"::{"line"::25,"character"::9},"end"::{"line"::25,"character"::47}},"targetSelectionRange"::{"start"::{"line"::25,"character"::22},"end"::{"line"::25,"character"::30}}}]}

1602684688897:Req:{"jsonrpc"::"2.0","id"::4,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/main.dart"},"position"::{"line"::31,"character"::9}}}
1602684689408:Req:{"jsonrpc"::"2.0","method"::"$/cancelRequest","params"::{"id"::4}}

1602684689409:Req:{"jsonrpc"::"2.0","id"::5,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/main.dart"},"position"::{"line"::29,"character"::8}}}
1602684689600:Res:{"id"::5,"jsonrpc"::"2.0","result"::[{"originSelectionRange"::{"start"::{"line"::29,"character"::2},"end"::{"line"::29,"character"::12}},"targetUri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/utils/hive_config.dart","targetRange"::{"start"::{"line"::4,"character"::0},"end"::{"line"::21,"character"::1}},"targetSelectionRange"::{"start"::{"line"::4,"character"::6},"end"::{"line"::4,"character"::16}}}]}

1602684693016:Req:{"jsonrpc"::"2.0","id"::7,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/main.dart"},"position"::{"line"::29,"character"::8}}}
1602684693526:Req:{"jsonrpc"::"2.0","method"::"$/cancelRequest","params"::{"id"::7}}

1602684693526:Req:{"jsonrpc"::"2.0","id"::9,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/main.dart"},"position"::{"line"::31,"character"::7}}}
1602684693674:Res:{"id"::9,"jsonrpc"::"2.0","result"::[]}

1602684703636:Req:{"jsonrpc"::"2.0","id"::11,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/main.dart"},"position"::{"line"::28,"character"::21}}}
1602684703638:Res:{"id"::11,"jsonrpc"::"2.0","result"::[]}

1602684703838:Req:{"jsonrpc"::"2.0","id"::12,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/main.dart"},"position"::{"line"::28,"character"::15}}}
1602684703839:Res:{"id"::12,"jsonrpc"::"2.0","result"::[]}

1602684703940:Req:{"jsonrpc"::"2.0","id"::13,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/main.dart"},"position"::{"line"::29,"character"::12}}}
1602684703943:Res:{"id"::13,"jsonrpc"::"2.0","result"::[{"originSelectionRange"::{"start"::{"line"::29,"character"::2},"end"::{"line"::29,"character"::12}},"targetUri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/utils/hive_config.dart","targetRange"::{"start"::{"line"::4,"character"::0},"end"::{"line"::21,"character"::1}},"targetSelectionRange"::{"start"::{"line"::4,"character"::6},"end"::{"line"::4,"character"::16}}}]}

1602684707354:Req:{"jsonrpc"::"2.0","id"::17,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/main.dart"},"position"::{"line"::29,"character"::10}}}
1602684708095:Res:{"id"::17,"jsonrpc"::"2.0","result"::[{"originSelectionRange"::{"start"::{"line"::29,"character"::2},"end"::{"line"::29,"character"::12}},"targetUri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/utils/hive_config.dart","targetRange"::{"start"::{"line"::4,"character"::0},"end"::{"line"::21,"character"::1}},"targetSelectionRange"::{"start"::{"line"::4,"character"::6},"end"::{"line"::4,"character"::16}}}]}

1602684710374:Req:{"jsonrpc"::"2.0","id"::23,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/utils/hive_config.dart"},"position"::{"line"::30,"character"::10}}}
1602684710374:Req:{"jsonrpc"::"2.0","method"::"$/cancelRequest","params"::{"id"::23}}

1602684710374:Req:{"jsonrpc"::"2.0","id"::24,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/utils/hive_config.dart"},"position"::{"line"::30,"character"::18}}}
1602684710374:Req:{"jsonrpc"::"2.0","method"::"$/cancelRequest","params"::{"id"::20}}

1602684712624:Req:{"jsonrpc"::"2.0","id"::29,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/main.dart"},"position"::{"line"::29,"character"::15}}}
1602684712624:Req:{"jsonrpc"::"2.0","method"::"$/cancelRequest","params"::{"id"::29}}

1602684712625:Req:{"jsonrpc"::"2.0","id"::30,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/main.dart"},"position"::{"line"::29,"character"::12}}}
1602684712803:Res:{"id"::30,"jsonrpc"::"2.0","result"::[{"originSelectionRange"::{"start"::{"line"::29,"character"::2},"end"::{"line"::29,"character"::12}},"targetUri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/utils/hive_config.dart","targetRange"::{"start"::{"line"::4,"character"::0},"end"::{"line"::21,"character"::1}},"targetSelectionRange"::{"start"::{"line"::4,"character"::6},"end"::{"line"::4,"character"::16}}}]}

1602684716214:Req:{"jsonrpc"::"2.0","id"::31,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/main.dart"},"position"::{"line"::29,"character"::10}}}
1602684716812:Res:{"id"::31,"jsonrpc"::"2.0","result"::[{"originSelectionRange"::{"start"::{"line"::29,"character"::2},"end"::{"line"::29,"character"::12}},"targetUri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/utils/hive_config.dart","targetRange"::{"start"::{"line"::4,"character"::0},"end"::{"line"::21,"character"::1}},"targetSelectionRange"::{"start"::{"line"::4,"character"::6},"end"::{"line"::4,"character"::16}}}]}

1602684720267:Req:{"jsonrpc"::"2.0","id"::35,"method"::"textDocument/definition","params"::{"textDocument"::{"uri"::"file::///Volumes/macData/Work/FlutterWork/my_project/lib/main.dart"},"position"::{"line"::29,"character"::9}}}
1602684720921:Res:{"id"::34,"jsonrpc"::"2.0","result"::[{"range"::{"start"::{"line"::29,"character"::2},"end"::{"line"::29,"character"::12}}}]}

I subtracted the timestamp of the request from the timestamp of the response, but they're all way under a second:

Screenshot 2020-10-27 at 12 11 21

This suggests the server isn't taking long to respond to the requests once it gets them - so maybe the time is either being spent in the client, or on the server before it picked up the request (for example, it's doing some blocking work).

It would be useful to get timestamps from the client as well as the server to compare. Could you try also enabling the Analysis Server log (note: this one is different to the instrumentation log, as it's captured by the client). Keep the instrumentation log enabled also, so we can compare timestamps in them.

Attach the logs or email them to logs@dartcode.org (note: the logs will include parts of your source code so don't use anything sensitive when reproducing) and I'll compare the timestamps to see if there's a delay in the server picking up the requests.

Thanks!

@DanTup DanTup modified the milestones: v3.16.0, v3.17.0 Oct 27, 2020
@RaviKavaiya
Copy link
Author

Okay, @DanTup I will do that when get free. Thanks for your time!

@RaviKavaiya
Copy link
Author

@DanTup I am attaching a small debug log.

The steps I followed:

1). I just opened this project: https://github.com/flutter/samples
(The whole samples folder in VS Code).

2). Then, I opened these files:
1. https://github.com/flutter/samples/blob/master/veggieseasons/lib/main.dart
2. https://github.com/flutter/samples/blob/master/veggieseasons/lib/data/local_veggie_provider.dart
Only 2 files open, nothing else. Then I closed the VS Code and deleted the log files.

3). Now, I opened VS Code. Waited for the analysis to complete. Again waited for few seconds.

4). Then, I just (cmd + clicked) the symbol on this line: https://github.com/flutter/samples/blob/2165099fc95b8926a541a7a8f1dce35ba4501d1b/veggieseasons/lib/data/local_veggie_provider.dart#L17 (From Season.winter word, I clicked the Season).

5). Closed VS Code.

Let me know, if you want any additional information / logs.
One thing I noticed that, when I click the symbol (cmd+click), while it was loading, it showed me Analyzing... in the status bar.

dbg_analyzer.txt
debug_instrumentation.txt

@DanTup
Copy link
Member

DanTup commented Nov 3, 2020

Thanks - there's definitely something a little strange going on here. When you ctrl+clicked, VS Code sent quite a few requests, many of which were immediately cancelled:

Screenshot 2020-11-03 at 10 30 09

It also sent a didOpen and then didClose immediately after each other (line 3+4 here) for a file, which makes no sense to me.

I'll do some testing here and see if I can figure out what it's doing. I don't know if it's the cause of the delays, but it definitely seems unexpected.

@DanTup
Copy link
Member

DanTup commented Nov 3, 2020

The first issue (the open/close events) appears to be a quirk of VS Code. I filed microsoft/vscode#109908 but then found that it was raised before (microsoft/vscode#84875) and the language extension had to work around it. Since we can't work around it for LSP (we don't control the client library) I've filed an issue about having the same workaround in the LSP client (microsoft/vscode-languageserver-node#683).

This is likely causing some of the problem, as it'll be triggering analysis (which contains synchronous work that will block the thread) before the navigation, which could then delay the navigation. If this was fixed, the analysis of the other file would not be started until after it's navigated to, which I think would solve it.

I'll try to repro all of the other requests being triggered though. They might be caused by the cursor moving while holding down ctrl, but I think they should be handled better (because we provide a range for the hover/definition).

@DanTup
Copy link
Member

DanTup commented Nov 3, 2020

I was unable to repro all the cancelled requests, but I suggest we re-test this once the issue above is addressed to see how things are then.

@DanTup DanTup modified the milestones: v3.17.0, On Deck Nov 3, 2020
@DanTup DanTup added the blocked on vs code / lsp / dap Requires a change in VS Code to progress label Nov 3, 2020
@DanTup DanTup added the upstream in vs code / lsp / dap Needs changing in VS Code, LSP or DAP protocols/libraries label Nov 3, 2020
@DanTup DanTup changed the title Plugin performance low (in LSP) Ctrl+Click on a symbol outside of your workspace is very slow Jan 26, 2021
@DanTup DanTup removed blocked on vs code / lsp / dap Requires a change in VS Code to progress upstream in vs code / lsp / dap Needs changing in VS Code, LSP or DAP protocols/libraries labels Mar 1, 2021
@DanTup DanTup modified the milestones: On Deck, v3.21.0 Mar 1, 2021
@DanTup
Copy link
Member

DanTup commented Mar 1, 2021

I believe the slow Go-to-Symbol issue will be fixed by dart-lang/sdk@ddd70f5. VS Code is still sending the open/close events, but now they get filtered out better if they won't do anything (which is almost all of the time for a hover like that).

The other issue mentioned here (slow rename) is tracked in #2231 so I consider this resolved (although that fix isn't available in a stable Flutter release yet).

If you still see issues when using an SDK that includes the change above (which right now may be just the dev/master channels), please let me know!

@DanTup DanTup closed this as completed Mar 1, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
in editor Relates to code editing or language features is bug
Projects
None yet
Development

No branches or pull requests

2 participants