Possible performance issues after updating to 3.60

[incendial]

Describe the bug VS Code started to freeze sometimes after switching between files, also seeing this in the dev console:

Also this (not sure, if related)

2023-02-27 16:19:43.874 [error] [Dart-Code.dart-code] provider FAILED
2023-02-27 16:19:43.874 [error] Error: DisposableStore is missing...
    at Q.l (/Applications/Visual Studio Code.app/Contents/Resources/app/out/vs/workbench/api/node/extensionHostProcess.js:98:45641)
    at Q.resolveCompletionItem (/Applications/Visual Studio Code.app/Contents/Resources/app/out/vs/workbench/api/node/extensionHostProcess.js:98:45499)
2023-02-27 16:19:43.876 [error] [Dart-Code.dart-code] provider FAILED
2023-02-27 16:19:43.876 [error] Error: DisposableStore is missing...
    at Q.l (/Applications/Visual Studio Code.app/Contents/Resources/app/out/vs/workbench/api/node/extensionHostProcess.js:98:45641)
    at Q.resolveCompletionItem (/Applications/Visual Studio Code.app/Contents/Resources/app/out/vs/workbench/api/node/extensionHostProcess.js:98:45499)
2023-02-27 16:19:43.876 [error] [Dart-Code.dart-code] provider FAILED
2023-02-27 16:19:43.876 [error] Error: DisposableStore is missing...
    at Q.l (/Applications/Visual Studio Code.app/Contents/Resources/app/out/vs/workbench/api/node/extensionHostProcess.js:98:45641)
    at Q.resolveCompletionItem (/Applications/Visual Studio Code.app/Contents/Resources/app/out/vs/workbench/api/node/extensionHostProcess.js:98:45499)
2023-02-27 16:29:45.063 [warning] TextEditor is closed/disposed

And this

2023-03-03 17:49:00.451 [error] [Dart-Code.dart-code] provider FAILED
2023-03-03 17:49:00.451 [error] TypeError: Cannot read properties of undefined (reading 'label')
    at shouldTriggerCompletionAgain (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.60.1/out/dist/extension.js:5474:39)
    at LspAnalyzer.<anonymous> (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.60.1/out/dist/extension.js:5556:25)
    at Generator.next (<anonymous>)
    at fulfilled (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.60.1/out/dist/extension.js:5381:58)
    at runNextTicks (node:internal/process/task_queues:61:5)
    at process.processImmediate (node:internal/timers:437:9)
2023-03-03 17:49:56.149 [warning] TextEditor is closed/disposed

To Reproduce No particular steps

Expected behavior No freezes

Screenshots See above

Please complete the following information:

• Operating System and version: macOS 12.6
• VS Code version: 1.75.1
• Dart extension version: 3.60.1
• Dart/Flutter SDK version: Dart SDK version: 2.19.2 (stable) (Mon Jan 23 11:29:09 2023 -0800) on "macos_x64"
• Target device (if the issue relates to Flutter debugging): -

[incendial]

I'm not sure that the freezes are related, if you have any advice on how to profile them better - I'd really appreciate that! Also hope it's not my code again 😅

[DanTup]

2023-03-03 17:49:00.451 [error] [Dart-Code.dart-code] provider FAILED 2023-03-03 17:49:00.451 [error] TypeError: Cannot read properties of undefined (reading 'label')

Hmm, this is odd - the only way I can see this happening is if our code completion had an undefined item in it.

Can you trigger this error reliably? Could you capture logs with Dart: Capture Analysis Server Logs and ensure ensure dart.maxLogLineLength is very high (or, capture an instrumentation log which doesn't truncate)?

Out of interest, did you just update VS Code too? (if so, it's possible something changed in VS Code rather than Dart-Code.. I don't think there are any changes around this code in the latest release 🤔)

[incendial]

I don't have steps, just noticed the freezes and checked the logs. I'll recheck them again after some time.

Out of interest, did you just update VS Code too?

No, it has the same version as when I opened the previous issues (though the update button is available).

[incendial]

I'll recheck them again after some time.

I'll actually just work with the open extension log output to see if anythings pops out.

[incendial]

@DanTup what about other errors, do you need any additional info?

[incendial]

Also noticed this

2023-03-06 11:08:17.956 [error] [Dart-Code.dart-code] provider FAILED
2023-03-06 11:08:17.956 [error] Error: Illegal value for `line`
    at w.t (/Applications/Visual Studio Code.app/Contents/Resources/app/out/vs/workbench/api/node/extensionHostProcess.js:95:966)
    at Object.lineAt (/Applications/Visual Studio Code.app/Contents/Resources/app/out/vs/workbench/api/node/extensionHostProcess.js:95:90)
    at IgnoreLintCodeActionProvider.convertResult (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.60.1/out/dist/extension.js:18156:31)
    at /Users/dimannich/.vscode/extensions/dart-code.dart-code-3.60.1/out/dist/extension.js:18149:52
    at Array.map (<anonymous>)
    at IgnoreLintCodeActionProvider.provideCodeActions (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.60.1/out/dist/extension.js:18149:27)
    at Object.<anonymous> (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.60.1/out/dist/extension.js:5594:68)
    at Generator.next (<anonymous>)
    at fulfilled (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.60.1/out/dist/extension.js:5381:58)

[incendial]

And I'm starting to think that the freezes I have are not connected to this extension, but I'll continue observing for a few more days

[DanTup]

@incendial an instrumentation log capturing around the times any errors like these happen would be useful. Be aware it will contain parts of your source code/open files though.

I have a feeling that last one could be a race condition when using plugins. Right now, most of the server (and plugins) work with offsets and lengths but LSP requires line/col. We can map these, but we need a consistent view of the file contents to do so. In the Dart part of the server we can capture the LineInfo the matches the content used to produce the fixes. However for plugins, we don't have access to this so we have to assume the content at the time we start computing fixes is the one the plugin uses. If you're typing quickly, it's possible this is not the case.

I can think of some possible fixes for this (like extending the plugin API to accept line/cols in addition to offset/lengths, or preventing the server from processing file-modification requests while it's computing code fixes), but these would require API and plugin changes, or potentially impact performance (@bwilkerson FYI).

And I'm starting to think that the freezes I have are not connected to this extension, but I'll continue observing for a few more days

I actually hit some freezes in VS Code over the weekend (on macOS), while running some integration tests. It was unresponsive enough that I couldn't do any debugging (I had to force kill), but I'll also keep my eyes open. My feeling is that we (the extension, running in another process) should not be able to cause VS Code to hang in that way so there's likely a VS Code issue, but that doesn't rule out that we're triggering it with something.

[incendial]

I have a feeling that last one could be a race condition when using plugins.

The thing is, this repo does not have plugins.

[incendial]

And there are like 8 errors in one day (but I haven't seen them previously).

[DanTup]

I have a feeling that last one could be a race condition when using plugins.

Actually, looking at the code further I think this issue could be client-side. It's also in code I think we might not need anymore. Doing some digging...

[incendial]

My feeling is that we (the extension, running in another process) should not be able to cause VS Code to hang in that way so there's likely a VS Code issue, but that doesn't rule out that we're triggering it with something.

Yeah, I have the same understanding that it's impossible to trigger with a background process. I had an idea that it might be due to 2 LSP servers spamming VS Code with diagnostics, but since you've also faced it, I'm not that sure now.

[DanTup]

Ok, the only explanation I can come up with for the "invalid line" error is:

• We send VS Code diagnostics
• Content is modified, causes VS Code to ask for Code Actions
• Our local "Ignore code action" provider checks the diagnostics to see if we should produce fixes for "// ignore"ing them but while trying to do some calculations, finds that the line number against one of the diagnostics is no longer valid

Since this code is all synchronous, this suggests VS Code could have given us stale diagnostics (it didn't update the locations as the content was modified?). This seems odd, however this code (producing "// ignore" fixes) is also somewhat unnecessary since the server is producing them (and has been since Dart v2.14). What I can't explain, is why this code is running at all - since it's only supposed to happen if the server doesn't provide the Ignore fixes. It makes me wonder if the server isn't producing those fixes for all the diagnostics that the local client version was.

I'd be interested in a log if you can share one when this happens. If you can't share logs for this project, maybe you could extract bits between the last publishDiagnostics entry before this error and the /codeAction entry when the error occurred.

I had an idea that it might be due to 2 LSP servers spamming VS Code with diagnostics, but since you've also faced it, I'm not that sure now.

We have seen perf issues with large numbers of diagnostics before, but my tests definitely don't produce many so I don't think it's related to that (at least in my case). I will have a go at trying to repro today though, and see if I can get some more info to help raise a VS Code issue.

[incendial]

Is there a way to get logged errors or I need to explicitly enable capturing?

[DanTup]

The best way to get logs is to enable the instrumentation log:

https://dartcode.org/docs/logging/#analyzer-instrumentation

This won't log the errors you're seeing in the VS Code error console though (none of our logs will do that without us adding lots of try/catches - which maybe we should do since https://github.com/microsoft/vscode/issues/45264 was marked out-of-scope). For now you'd need to notice that error and then grab a copy of the log and find the relevant range of lines.

(note: that log can get very large, since it logs all traffic between VS Code the analysis server).

[DanTup]

@incendial do you use cannot-ignore in analysis-options? That's one way I can see that server would not produce ignore-fixes but the client would still try. If that's the only case, then I think dropping the local client-side ignore fixes would be fine (better, in fact).

[incendial]

Nope 🙂

[incendial]

I'll set up the instrumentation logs and get back when I see the problem again. But this week I mainly do non-dart related work, so this might take a while.

[DanTup]

np, let me know if you find anything.

I haven't been able to get VS Code to freeze again while running integration tests, but I will add some try/catch logging for both the issues above to see if running my tests can trigger them.

Edit: Seems like the tests don't trigger the issue.

[bwilkerson]

Since this code is all synchronous, this suggests VS Code could have given us stale diagnostics (it didn't update the locations as the content was modified?).

The following scenario seems plausible to me:

1. Server sends diagnostics for a given file.
2. The user edits the file.
3. VS Code tells the server that the file has changed.
4. VS Code asks for quick fixes, passing the diagnostics it last received at (1).
5. Server sends updated diagnostics for the file modification at (3).
6. Server sends quick fixes for the diagnostics returned at (5), which are different than the ones sent from VS Code at (4).

I don't know of any way to prevent the mismatch of diagnostics in the plugin, so I'm strongly in favor of making sure that server is always producing '// ignore' fixes when they're appropriate and dropping the client side support.

[DanTup]

Sorry, there's probably some missing context from above. Specifically for the issue about the line number above, the error is occurring in a client-side provider of CodeActions (that is, they are not going to the server). This was how we provided the "Ignore foo_error" code actions before adding them to the server.

So during (4), VS Code invokes this local provider, and it does indeed pass the "last known" diagnostics. However, while the file was being modified in (2), VS Code is updating the locations of diagnostics based on those edits (otherwise the squiggles would get out of date). I would expect that the local CodeActions provider would get a consistent view of the world at the time it is called (and since it has no async code, that should remain consistent).

Perhaps rather than just removing the local provider, I could push a pre-release version that just catches the error and prints additional debugging info to the console. That way if @incendial can repro with that version, we can see where the server isn't producing these (but the client tried to) before we remove it.

[DanTup]

Turns out I had confused myself when I was writing the above. Although this provider is synchronous, it's not invoked by VS Code. We invoke it in LSP middleware (because we need to wait for the server results to see if it had already added an Ignore entry).

So there is some async here. I think the reason the server isn't producing an ignore is that the file has just been modified to remove the diagnostic, and we try to build one form the stable diagnostic, but when converting the line to an offset, VS Code is giving us "live" data.

I'm going to remove the local provider, but before I do @incendial I've pushed a new pre-release version of the Dart extension (v3.61.20230306) that adds additional logging. If you ensure you're on the pre-release and can trigger this again, the console should contain more info like this:

A screenshot of that may be very useful :-)

[incendial]

Deal, I'll switch to prerelease, but keep in mind

I'll set up the instrumentation logs and get back when I see the problem again. But this week I mainly do non-dart related work, so this might take a while.

So if you're down to wait for a week or two - that'd be great, but I can't promise you that the problem will appear again

[DanTup]

@incendial yep, understood. That's fine. If we get to the end of the month and it's release time, I may revert (or alter) that logging to avoid being too spammy, but we can always put it back in to the pre-release that goes out after the stable release (which I always do so VS Code always shows the "switch to pre-release" option).

[DanTup]

Oh, this only covered one of the issues above. I could also add additional verbose logging for the completion.label issue. I'll do that tomorrow and push another pre-release. Assuming you have auto-updates on in VS Code, it'll automatically move you along to the next one.

[DanTup]

I pushed another pre-release today that including some logging for the completion item issue too (v3.61.20230307). It might take 30 min to show up in VS Code, but when you get back to this if you trigger either of the issues that had stack traces above, there should be some additional info in the console.

[incendial]

New day, new issue 😅

workbench.desktop.main.js:615   ERR Illegal argument: character must be non-negative: Error: Illegal argument: character must be non-negative
    at w (/Applications/Visual Studio Code.app/Contents/Resources/app/out/vs/workbench/api/node/extensionHostProcess.js:7:1267)
    at new p (/Applications/Visual Studio Code.app/Contents/Resources/app/out/vs/workbench/api/node/extensionHostProcess.js:94:13423)
    at new n (/Applications/Visual Studio Code.app/Contents/Resources/app/out/vs/workbench/api/node/extensionHostProcess.js:94:14913)
    at asRange (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.61.20230307/out/dist/extension.js:39344:24)
    at asLocation (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.61.20230307/out/dist/extension.js:39675:66)
    at asInlayHintLabelPart (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.61.20230307/out/dist/extension.js:40113:31)
    at convertBatch (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.61.20230307/out/dist/extension.js:41685:25)
    at Object.map (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.61.20230307/out/dist/extension.js:41694:17)
    at asInlayHint (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.61.20230307/out/dist/extension.js:40088:27)
    at convertBatch (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.61.20230307/out/dist/extension.js:41717:31)
    at async Object.mapAsync (/Users/dimannich/.vscode/extensions/dart-code.dart-code-3.61.20230307/out/dist/extension.js:41725:17)
    at async ee.provideInlayHints (/Applications/Visual Studio Code.app/Contents/Resources/app/out/vs/workbench/api/node/extensionHostProcess.js:98:49977)

Got like 11 of them today, no steps though. I didn't find any code like the mentioned above in the repo, is it already removed?

[DanTup]

I've moved that one to https://github.com/Dart-Code/Dart-Code/issues/4436.

I suspect it's similar to https://github.com/dart-lang/sdk/issues/51515, but this is inlay hints not implementations. I'll see if I can figure out a repo and follow up on that issue.

[incendial]

Looks like having the extension host logs always open is useful 😁. I'm actually down to have any sentry-like automatic logs sending to you, to be honest. If this becomes available, let me know.

[incendial]

Also still have "DisposableStore is missing..." from time to time, do you know what it's about?

[DanTup]

hmmm no, not sure about that. Could you paste it into a new issue (and feel free to create new issues for any different error you see, it's probably easier to track them individually).

[incendial]

It's mentioned here https://github.com/Dart-Code/Dart-Code/issues/4421#issue-1608942126 (the second one), so that's why I'm bringing it up here, not separately

[DanTup]

Yep, understood - I'm not sure it's related to the performance issues.. although re-reading the errors I do wonder whether it's related to the "undefined label" issue. I don't suppose any of the extra logging has been showing up?

[incendial]

No, nothing

[DanTup]

@incendial are you still seeing either of the other errors from above (undefined label, illegal value for "line")? If so, can you check you're still on the pre-release extension and it doesn't show a "Reload" button (in which case the old version may still be running).

[incendial]

Nope, haven't seen them since the report. I'm definitely on the pre-release

[incendial]

These are the new logs you've added, right?

[DanTup]

@incendial yes! Something is definitely not right there, you seem to have gotten code completion for an empty string :(

Can you reproduce this reliably by invoking completion in those given Document/positions?

[incendial]

Sorry, but have no clue how to repro, just noticed it in the console. Also no errors were shown. I'll try to pay more attention.

[incendial]

Actually, I might have an idea, just a sec

[incendial]

Nope, it's not it, but sometimes in the visitor files (which are part files) the completion stops working eventually and I need to press ESC + enter another symbol to trigger it. It's not what triggers the error though (or I didn't find extra steps coz that's what I was doing in this file previously.

https://user-images.githubusercontent.com/21116742/226864490-46f656ef-0267-4196-a595-526f6a421fd5.mov

[incendial]

Ah, and sorry for the wording in the example, no pun intended 🤦‍♂️

[DanTup]

the completion stops working eventually and I need to press ESC + enter another symbol to trigger it

Hmm, that's interesting. There is a time budget on completion, so sometimes we might return an incomplete list. However, this should be flagged as such so that when you type the next character, VS Code will go back to the server. Could you file another bug specifically for this issue with the video above?

If you can repro on a public project I could try testing with, or get a log (you can use Dart: Capture Analyzer Logs and just capture the bit where this is happening), that may be helpful.

As for the empty strings - I'm not sure what's causing them but I wonder if maybe they could be unnamed/default constructors. I would expect them to have parens on the end though. Could you confirm all of the dart.* settings you have in your User/Workspace settings? (things like dart.completeFunctionCalls etc.)

Thanks!

[incendial]

If you can repro on a public project I could try testing with, or get a log (you can use Dart: Capture Analyzer Logs and just capture the bit where this is happening), that may be helpful.

This is a public project, https://github.com/dart-code-checker/dart-code-metrics/blob/master/lib/src/analyzers/lint_analyzer/rules/rules_list/use_setstate_synchronously/visitor.dart#L23 can you try here?

things like dart.completeFunctionCalls etc.

"dart.closingLabels": false, "dart.analyzeAngularTemplates": false, "dart.debugExternalPackageLibraries": true, "dart.checkForSdkUpdates": false, "dart.runPubGetOnPubspecChanges": "never",

I wonder if maybe they could be unnamed/default constructors

not sure about that, it was reported to this expression declaration is ClassDeclaration.

Could you file another bug specifically for this issue with the video above?

In this repo?

[DanTup]

In this repo?

Yep, here is fine.

I'll have a poke around and see if I can repro - thanks!

[DanTup]

(Posting this here while it's in my mind, but if you file a new issue I'll move this comment to it to avoid this one becoming difficult to track)

Ok, I think I understand the issue with completion saying "no items found". The problem is that we have a time budget on completion, and after that time we will just return whatever we have computed with a flag that says "this list is incomplete". We do this because VS Code doesn't let us "stream" completion results, so if we waited too long, you wouldn't get any completions.

When we set the isIncomplete flag, VS Code knows to ask the server again when you next type a character, because we may return additional results. However, this doesn't work if the computed list was empty. I've filed https://github.com/microsoft/vscode/issues/155738 about this - it seems to cause grief for a number of extensions (there are lots of commits tagged against that issue trying to work around it).

The reason you're triggering this a lot, is that code completion is very slow where you're invoking it here. It's spending 2.6s inside OverrideContributor trying to find the methods to include as overridable (I suspect this is probably due to a large type hierarchy, but I haven't profiled it to see exactly where the time goes yet):

(name: OverrideContributor, count: 1, elapsed: 0:00:02.631951, elapsedSelf: 0:00:02.631951)

[DanTup]

I was able to reproduce the issue with the empty label - I think it may be related to unnamed extensions showing up in completion. I've split this off into https://github.com/Dart-Code/Dart-Code/issues/4451.

[DanTup]

I suspect this is probably due to a large type hierarchy, but I haven't profiled it to see exactly where the time goes yet

Actually, it turns out this bad completion performance is the same cause as https://github.com/Dart-Code/Dart-Code/issues/4364. That issue turns up in Snippets inside part files, because each snippet is using DartFileEditBuilder to be able to compute imports, but doing so on a part file triggers analysis of the containing library (the results of which are not cached, and therefore are slow).

The same is true for OverrideContributor, it's also using DartFileEditBuilder to add imports, and this requires resolving the containing library.

I don't have a quick fix for this unfortunately, but I suspect if you were to move off part files you'd find some things in these files (completion, code actions) would perform significantly better.

[incendial]

I don't have a quick fix for this unfortunately, but I suspect if you were to move off part files you'd find some things in these files (completion, code actions) would perform significantly better.

Yep, my other version doesn't have part files (removing them also reduced the overall memory consumption), but feels like that removing parts shouldn't be a proper solution to this problem 🙂. Anyway, thank you for looking into it! Do you still want to have a separate issues for that?

[DanTup]

feels like that removing parts shouldn't be a proper solution to this problem 🙂

Agreed, it's just an option that exists today that's worth considering if the problem is very bad.

Do you still want to have a separate issues for that?

Nope, it's ok - I've updated the title of #4364 to note both snippets and overrides, since they're basically the same problem.

I've landed a fix in the server for the missing label issue. Have you had any look reproducing the InlayHints issue since the extra logging was added?