Dart-Code
Run/Debug inlay hints taking a long period to be clickable again
Describe the bug While debugging you can see the "Run | Debug" inlay hints but making changes on other files makes them unclickable for a long period.
To Reproduce Steps to reproduce the behavior:
- Using https://github.com/FMorschel/sdk/tree/unnecessary-inner-casts 1st commit
- Open, wait for the analysis
- Open the
fix_internal.dart - Open the test file
remove_unnecessary_inner_casts_test.dart - In fix_internal find the warning
UNNECESSARY_CAST - Add the
RemoveUnnecessaryInnerCastsclass there and trigger "add import" from the auto-complete - Open the tests file to see the buttons for "Run | Debug" (hover the mouse on them to see when they are enabled) once it enables them you can see that everything has completed
Expected behavior For them to be clickable faster.
Logs
- With everything closed and no other changes made, added the class server_workspace_not_loaded.zip
- With everything closed, removed the class and import and readded them server_workspace_loaded.zip
Please complete the following information:
Workspace Environment
Dart Code extension: 3.99.20241007
Flutter extension: 3.99.20240930 (activated)
App: Visual Studio Code
App Host: desktop
Version: win 1.94.2
Workspace type: Dart (LSP) (Multiroot)
Workspace name: server2 (Workspace)
Dart (3.6.0-edge.dbc771f72ccc82a654f8294803574252c58e16b8): C:\Users\felip_0vh5fa6\dart
Flutter (3.24.3): C:\Users\felip_0vh5fa6\.puro\envs\stable\flutter (No device)
Output from 'dart info'
C:\Users\felip_0vh5fa6\dart\bin\dart.exe info
If providing this information as part of reporting a bug, please review the information below to ensure it only contains things you're comfortable posting publicly.
General info
- Dart 3.6.0-edge.dbc771f72ccc82a654f8294803574252c58e16b8 (main) (Fri Oct 4 15:26:27 2024 +0000) on "windows_x64"
- on windows / "Windows 10 Pro" 10.0 (Build 22631)
- locale is pt-BR
Project info
- sdk constraint: '>=3.3.0 <4.0.0'
- dependencies: _fe_analyzer_shared, analysis_server_plugin, analyzer, analyzer_plugin, args, collection, convert, crypto, dart_style, dtd, http, json_rpc_2, language_server_protocol, linter, memory_usage, meta, path, pub_semver, stream_channel, telemetry, test, unified_analytics, vm_service, watcher, yaml, yaml_edit
- dev_dependencies: analyzer_utilities, cli_util, lints, logging, matcher, test_descriptor, test_reflective_loader, web_socket_channel
Process info
| Memory | CPU | Elapsed time | Command line |
|---|---|---|---|
| 0 MB | -- | dart.exe | |
| 0 MB | -- | dart.exe | |
| 0 MB | -- | dart.exe |
I can't reproduce this, but while reviewing the logs I remembered that these CodeLenses do not come from the server, but are made client-side using the outline data. When we try to get them, we call:
this.analyzer.fileTracker.waitForOutlineWithLength(document, expectedLength, token);
The waitForOutlineWithLength call fetches the current outline for a file and waits up to 5s. We had some bugs in this area in the past - https://github.com/Dart-Code/Dart-Code/issues/5047 and https://github.com/Dart-Code/Dart-Code/issues/5048. Probably these are related (although if it's this CodeLens not getting outline, I'd expect the CodeLenses to disappear not become accessible... so maybe another CodeLens is timing out).
Ok, after some more digging in the log I found this which I think occurred at the time you saw the delay:
16:39:47.939,Req,{"jsonrpc":"2.0","id":429,"method":"workspace/executeCommand","params":{"command":"dart.edit.fixAll","arguments":[{"path":"C:\\Users\\felip_0vh5fa6\\Documents\\Projects\\clones\\dart-sdk2\\sdk\\pkg\\analysis_server\\test\\src\\services\\correction\\fix\\remove_unnecessary_inner_casts_test.dart","autoTriggered":true}]},"clientRequestTime":1728661187712}
16:39:55.628,Res,{"id":429,"jsonrpc":"2.0","result":null}
This is a 7 second request for "dart.edit.fixAll". I presume you have this configured to run on-save (it says autoTriggered)? I tried enabling this, however it does not take anything like 7s for me. I noticed you have TODOs enabled (which increases the number of diagnostics) so I tried enabling that too, but it still is a fraction of a second.
So, does the issue go away if you don't have fix-all executed? If so, when you reproduce (with fix all), do you see a low request for executeCommand in the Analyzer Diagnostics Timing page? (If so, can you get the details).
Which log is this one? Analyzer?
I found something weird. My workspace settings file had:
"editor.codeActionsOnSave": {
"source.organizeImports": "always",
"source.sortMembers": "always"
},
But my user settings had fixAll set. I've removed it to test. I'm not sure if I was expected to set it again on the workspace level to never or something.
It is instantaneous when having only those and not the fixAll on the user level.
-- This might also be what I asked you once about the long analyzer time when changing branches. I sometimes also see a long wait time for using fixes whenever I've opened the project. Almost always I end up restarting the analyzer because of it (it is for some weird reason faster).
This is what you asked for:
I wonder if VSCode itself is taking a long time to do something between that ' fixErrorsForFileand theexecuteCommand` (and maybe also after it to enable the inlay hints).
Yes, this is exactly what I was looking for. It's not VS Code, because the request on the server itself took 4.3s in the screenshot above.
However, it looks like the time is not spent in actually in the fixing, which makes me think it may be spent in analysis, which we're not currently timing.
I will open a change to add some additional detail to this timing. In the meantime, could you click on the "Analysis Driver Timings" page (second item in the left nav in your last screenshot), then get set up to reproduce this, then click the "Reset" button to clear the timings, reproduce the issue, then reload that page and get the timings from that page? Thanks!
Here it is. Anything else? I've not closed anything yet.
(name: <scheduler>, count: 0, elapsed: 0:00:00.000000, elapsedSelf: -0:00:05.337362)
(name: getUnitElement, count: 12, elapsed: 0:00:00.001300, elapsedSelf: 0:00:00.000524)
(name: libraryContext, count: 12, elapsed: 0:00:00.000776, elapsedSelf: 0:00:00.000746)
(name: libraryCycle, count: 12, elapsed: 0:00:00.000030, elapsedSelf: 0:00:00.000030)
(name: analyzeFile, count: 490, elapsed: 0:00:05.336062, elapsedSelf: 0:00:05.302605)
(name: libraryContext, count: 490, elapsed: 0:00:00.033457, elapsedSelf: 0:00:00.031378)(bytesGet: 40025, cycleCount: 5, libraryCount: 5, libraryLoadCount: 5)
(name: libraryCycle, count: 490, elapsed: 0:00:00.002079, elapsedSelf: 0:00:00.002079)
Thanks - nothing more for now, but I'll do some digging into this. While looking at the Fix All handler to see why it was 5s but that time wasn't attributed anywhere, I found we were needlessly fetching a resolved AST at the start. Fixing that won't make it (much) faster, but it should cause the time to be correctly attributed to the child operations (likely getResolvedLibrary which would've previously got the cached version). I opened https://dart-review.googlesource.com/c/sdk/+/390600 for that.
@FMorschel did you manage to try excluding this folder from antivirus to see if it makes a difference? If not, can you get a new screenshot of the timings above using a latest bleeding edge build that has my change above?
I've added it but haven't had time to work on the SDK yet. I did get the SDK from today so I'm on the latest changes as well. I'll see if I can find some time later today to test this out.
I also just saw:
- https://github.com/Dart-Code/Dart-Code/issues/5319
- https://github.com/dart-lang/sdk/issues/56307 (your comment on the above issue)
They seem a little related to me since I have auto-save set to 1s and I had fixAll set to always. I'll take a longer look at them later and keep you updated.
It seems that adding .dartServer to the exclusions has fixed this issue. Although I still see > 50s latency (probably time somewhere back) when changing branches for analyzing. I'll see if I can repro this in a way to send you a screenshot of the timings. If you agree we can close this and I can open a new issue for this. Thanks!
Changing branches will result in a lot of code to reanalyze in a short space of time so I would expect that to take a little while, though whether 50s is reasonable I'm not sure - it may be worth filing an SDK issue with some steps to repro (eg. if this is working on the analyzer, details of two hashes you switched between and which folder(s) are in the workspace).
@FMorschel is there anything to do here? If the remaining issue is that analysis after changing branches is slow, we should track/discuss that in the SDK tracker since it's not specific to the VS Code extension (and can't be improved here).
I don't think there is anything left to do here. Thanks! When I have some time I'll repro and open the issue linking it back here as well.