Ctrl+Hover over an OCI module path causes the extension to get stuck with extremely high CPU & memory utilization

[jtomkiew-mng]

Does this occur consistently? No, from time to time.

Repro steps:

I have no repro steps (this is a terrible bug report, I know), but I use Bicep through VSCode, and from time to time I notice my laptop stops charging (while being connected) which is caused by Bicep .NET host process going "insane", constantly recycling memory (up to 20GB, then back to 10GB over a minute or so).

I recently (this week) did az bicep upgrade, not sure if related.

Last time I've encountered this was about 4-6 months ago.

Feel free to ask for details, as I have no idea what should I provide here.

Error

This error is after I force close the .NET process, which might not be useful.

Action: bicep.lsp-error
Error type: Error
Error Message: Error: write EOF

Version: 0.25.53
OS: win32
OS Release: 10.0.22631
Product: Visual Studio Code
Product Version: 1.86.2
Language: en

Call Stack

extension.js:2:2441034extension.js:2:2441034
callWithTelemetryAndErrorHandlingSync extension.js:2:650898
Object.error extension.js:2:2440889
LanguageClient.handleConnectionError extension.js:2:1863736
extension.js:2:1862541extension.js:2:1862541
extension.js:2:1861886extension.js:2:1861886
CallbackList.invoke extension.js:2:1806072
Emitter.fire extension.js:2:1806860
readErrorHandler extension.js:2:1797482
CallbackList.invoke extension.js:2:1806072
Emitter.fire extension.js:2:1806860
SocketMessageReader.fireError extension.js:2:1814778
Socket.<anonymous> extension.js:2:1816502

[anthony-c-martin]

To debug this further, I think we'd need a memory dump. I suggest we keep this open, and next time you run into it (or anyone else does), please capture a memory dump using these instructions.

The memory dump may contain sensitive information, so please do not share it directly on GitHub. Reach out to me via email (antmarti at microsoft dot com), and I'd be happy to set up a way to share it securely.

[jtomkiew-mng]

Boop. I'll provide more information if I encounter this issue next time.

[jtomkiew-mng]

I've encountered this again, I'll be contacting @anthony-c-martin over email.

Pictured: one Bicep dotnet process is eating lots of ram and increasing, the other code process (not sure if directly related to Bicep) is doing lots of processing. VS Code is otherwise idle.

[slavizh]

I am noticing this as well. It is coming from VSC window where I have bicep parameters files opened with using statements towards container registry.

You can also see this weird behavior happening. If it stops doing that the ram and CPU go down.

[anthony-c-martin]

I am noticing this as well. It is coming from VSC window where I have bicep parameters files opened with using statements towards container registry.

This is odd. Do you notice any patterns about when this occurs? Does it always happen when using a bicepparam file referencing a registry?

Could you try enabling LSP tracing:

And sharing the "Bicep" output when this is happening:

Note that there shouldn't be anything sensitive logged with just "Messages" enabled, but "Verbose" may include sensitive information such as contents of files. "Messages" is probably enough for now.

[slavizh]

Yes, it always happens when having bicepparam files. I basically have 3-5 or more VSC windows opened. One of those windows is always a project where I have only bicepparam files. Usually have a few such files open in that window. They either reference bicep registry files or the using statement is empty string. The project itself contains hundreds of bicepparam files. I cannot understand when exactly happens but when I work on that project I usually add the bicep registry reference in the using statement or force restore in order to update the reference. The other projects (VSC windows) are only with bicep files and for them I do not notice that problem. I know that this is the exact window/process because when I kill it VSC asks me if I want to re-open it. I will enable the tracing and see if it appears again I can save the results. If it contains sensitive information will send information I will send it in private.

[anthony-c-martin]

@jtomkiew-mng looking at your memory dump, one thing that is very unusual is that there's a huge number of queued language server requests (almost 1.3 million!). Of those I've checked, the vast majority appear to be of kind textDocument/bicepExternalSource.

So my initial instinct here is that the VSCode extension is getting caught in some sort of loop where it is spamming the language service with requests to get an external source file, and the service is simply unable to keep up with the rate of requests coming through. This could also fit with the odd behavior @slavizh was seeing in the gif where it looked like diagnostics were constantly being regenerated, and "external source file" lookups are only relevant for registry modules.

@StephenWeatherford can you think of anything that could be going on here?

[jtomkiew-mng]

FYI, in our setup, we have a bunch of .bicepparam files referencing local .bicep file that references bicep module hosted on private Azure CR.

[slavizh]

2024-04-05T062950.784Z info Current.txt
here is a dump of the trace. The issue starts at around 4:10 when I started editing using statement. Before that way earlier I have edited using statement on another file and did not had the problem. I have killed the process but the last traces just repeat themselves.

[anthony-c-martin]

I managed to repro this myself!

Steps:

1. Open the following file in an editor window:

   module foo 'br/public:avm/res/network/public-ip-address:0.4.0' = {
     name: 'adsf'
     params: {
       name: 'asfd'
     }
   }

2. Hold Ctrl (Cmd on Mac) and hover the cursor over the path.

I can also confirm that this occurs without external sources functionality enabled - in @slavizh's example, there are no requests of type textDocument/bicepExternalSource.

This seems possibly related to microsoft/vscode#78453. I think we might need guidance from VSCode on how to handle this better. It's worth looking over some of the PRs linked in the above issue for how this was handled in other language servers. It's also not clear to me whether this is a regression in VSCode, or has always been the case.

While we figure out how to solve the root cause, the simplest workaround I know of for now is to reload the window - that'll kill the language service and start a new one:

[StephenWeatherford]

@anthony-c-martin Can you still repro with your example above? With 1.88.1 (stable) and 1.89.0-Insider, I don't see the doc getting closed at all, no matter how many times I cmd+hover:

[Trace - 1:44:00 PM] Sending request 'textDocument/definition - (11)'.
[Trace - 1:44:00 PM] Received response 'textDocument/definition - (11)' in 67ms.
[Trace - 1:44:00 PM] Sending request 'textDocument/bicepExternalSource - (12)'.
[Trace - 1:44:00 PM] Received notification 'telemetry/event'.
[Trace - 1:44:00 PM] Received response 'textDocument/bicepExternalSource - (12)' in 34ms.
[Trace - 1:44:00 PM] Sending request 'textDocument/bicepExternalSource - (13)'.
[Trace - 1:44:00 PM] Received notification 'telemetry/event'.
[Trace - 1:44:00 PM] Received response 'textDocument/bicepExternalSource - (13)' in 12ms.
[Trace - 1:44:00 PM] Sending notification 'textDocument/didOpen'.
[Trace - 1:44:01 PM] Sending request 'textDocument/hover - (14)'.
[Trace - 1:44:01 PM] Received response 'textDocument/hover - (14)' in 8ms.
[Trace - 1:44:08 PM] Sending request 'textDocument/definition - (15)'.
[Trace - 1:44:08 PM] Received response 'textDocument/definition - (15)' in 7ms.
[Trace - 1:44:08 PM] Sending request 'textDocument/hover - (16)'.
[Trace - 1:44:08 PM] Received response 'textDocument/hover - (16)' in 5ms.
[Trace - 1:44:08 PM] Sending request 'textDocument/documentHighlight - (17)'.
[Trace - 1:44:08 PM] Received response 'textDocument/documentHighlight - (17)' in 6ms.
[Trace - 1:44:08 PM] Sending request 'textDocument/definition - (18)'.
[Trace - 1:44:08 PM] Received response 'textDocument/definition - (18)' in 3ms.
[Trace - 1:44:09 PM] Sending request 'textDocument/documentHighlight - (19)'.
[Trace - 1:44:09 PM] Received response 'textDocument/documentHighlight - (19)' in 43ms.
[Trace - 1:44:09 PM] Sending request 'textDocument/documentLink - (20)'.
[Trace - 1:44:09 PM] Received response 'textDocument/documentLink - (20)' in 68ms.
[Trace - 1:44:09 PM] Sending request 'textDocument/codeLens - (21)'.
[Trace - 1:44:09 PM] Received response 'textDocument/codeLens - (21)' in 147ms.

[anthony-c-martin]

No - I can no longer repro this! I'm also using VSCode 1.88.1.

[StephenWeatherford]

Cool!

@jtomkiew-mng @slavizh I'm going to close for now, since it appears to have been fixed (probably by vscode, 1.88.1+). But please feel free to reopen if it's still an issue. Thanks!

[slavizh]

@StephenWeatherford I had experienced the issue yesterday with 1.88.1. Had to kill the .net process and the VSC window.

[jtomkiew-mng]

@StephenWeatherford hm, from a 0% CPU usage on a single VSCode 1.88.1 instance while a single bicep template tab is open, if I then Ctrl+Hover over the module reference (br:customacr.azurecr.io/..., it's already locally cached), CPU usage instantly jumps to 20-30% and memory usage starts accumulating (up to 1.2GB from 500MB after ~5 minutes).

(this is an animated GIF, seems you need to click on it to animate, at least on my end)

If I do Developer: Reload Window it calms down instantly.

I would say it still is an issue.

[anthony-c-martin]

Thanks for confirming this is still a problem - I've re-opened the issue.

[StephenWeatherford]

Thanks. I guess I'll need a way to repro. Can you repro with Anthony's simple .bicep example? Or other public repo. Anything else that might help? Thanks!

[jtomkiew-mng]

@StephenWeatherford yes, the example reproduces it as well on my end:

VSCode version info:

Version: 1.88.1 (user setup)
Commit: e170252f762678dec6ca2cc69aba1570769a5d39
Date: 2024-04-10T17:41:02.734Z
Electron: 28.2.8
ElectronBuildId: 27744544
Chromium: 120.0.6099.291
Node.js: 18.18.2
V8: 12.0.267.19-electron.0
OS: Windows_NT x64 10.0.22631

[StephenWeatherford]

Seeing this in telemetry as an abnormally high occurences of vs-code/externalsourcerequest/success.