Consistent high cpu load in latest preview (v.2.48.31)

[tverboon]

Type: Bug

Issue Description

While loading projects CPU usage is consistently around and above 100% CPU. That's 1 core on Mac.

Steps to Reproduce

Start VSCode and load our solution with latest C# plugin.

Expected Behavior

After loading projects cpu usage should come down.

Actual Behavior

Keeps opening and closing files causing high cpu usage.

Logs

Latest preview v2.48.31

[LanguageServerHost] No request parameters given, using default language handler
[LanguageServerHost] [05:42:34.763][Start]workspace/buildOnlyDiagnosticIds
[LanguageServerHost] [05:42:34.763][Start]textDocument/didOpen
[LanguageServerHost] didOpen for virtualcsharp-razor:///Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Views/Shared/DisplayTemplates/EmailAddress.cshtml__virtual.cs
[LanguageServerHost] [05:42:34.763][End]textDocument/didOpen
[LanguageServerHost] [05:42:34.763][End]workspace/buildOnlyDiagnosticIds

Latest release v2.45.25

[LanguageServerHost] No request parameters given, using default language handler
[LanguageServerHost] [05:28:56.201][Start]textDocument/didOpen
[LanguageServerHost] didOpen for virtualcsharp-razor:///Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Views/Shared/DisplayTemplates/EmailAddress.cshtml__virtual.cs
[LanguageServerHost] [05:28:56.201][End]textDocument/didOpen

I hoped to only paste logs that are relevant, but I can upload everything when this is not enough.

The most obvious difference is, the parent directory file path is duplicated in the latest preview release.

/Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Views/Shared/DisplayTemplates/EmailAddress.cshtml__virtual.cs

It also seems to be only happening with razor files.

Razor logs:

[Warn  - 7:41:08 AM] [LSP][LanguageServer.GeneratedDocumentPublisher] Skipping publish of Html for /Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Views/Shared/DisplayTemplates/EmailAddress.cshtml because we've already published version 5, and this request is for 1.
[Warn  - 7:41:08 AM] [LSP][LanguageServer.GeneratedDocumentPublisher] Skipping publish of C# for /Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Views/Shared/DisplayTemplates/EmailAddress.cshtml because we've already published version 5, and this request is for 1.
[Warn  - 7:41:16 AM] [LSP][LanguageServer.GeneratedDocumentPublisher] Skipping publish of Html for /Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Views/Shared/DisplayTemplates/EmailAddress.cshtml because we've already published version 5, and this request is for 2.
[Warn  - 7:41:16 AM] [LSP][LanguageServer.GeneratedDocumentPublisher] Skipping publish of C# for /Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Views/Shared/DisplayTemplates/EmailAddress.cshtml because we've already published version 5, and this request is for 2.
[Warn  - 7:41:16 AM] [LSP][LanguageServer.GeneratedDocumentPublisher] Skipping publish of Html for /Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Views/Shared/DisplayTemplates/EmailAddress.cshtml because we've already published version 5, and this request is for 1.
[Warn  - 7:41:16 AM] [LSP][LanguageServer.GeneratedDocumentPublisher] Skipping publish of C# for /Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Views/Shared/DisplayTemplates/EmailAddress.cshtml because we've already published version 5, and this request is for 1.
[Warn  - 7:41:16 AM] [LSP][LanguageServer.GeneratedDocumentPublisher] Skipping publish of Html for /Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Views/Shared/DisplayTemplates/EmailAddress.cshtml because we've already published version 5, and this request is for 2.
[Warn  - 7:41:16 AM] [LSP][LanguageServer.GeneratedDocumentPublisher] Skipping publish of C# for /Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Views/Shared/DisplayTemplates/EmailAddress.cshtml because we've already published version 5, and this request is for 2.
[Client - 7:41:16 AM] File '/Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web/Views/Shared/DisplayTemplates/EmailAddress.cshtml' didn't exist in the Razor document list. This is likely because it's from outside the workspace.

The last line is warning that the file didn't exist, I am sure it doesn't because that path also has the duplicate parent folder.

Environment information

VSCode version: 1.93.1
C# Extension: 2.48.31
Using OmniSharp: false

Dotnet Information

.NET SDK: Version: 8.0.104 Commit: 034f91fcc0 Workload version: 8.0.100-manifests.9f663350

Runtime Environment:
OS Name: Mac OS X
OS Version: 14.6
OS Platform: Darwin
RID: osx-arm64
Base Path: /usr/local/share/dotnet/sdk/8.0.104/

.NET workloads installed:
Workload version: 8.0.100-manifests.9f663350
There are no installed workloads to display.

Host:
Version: 8.0.4
Architecture: arm64
Commit: 2d7eea2529

.NET SDKs installed:
6.0.300 [/usr/local/share/dotnet/sdk]
7.0.202 [/usr/local/share/dotnet/sdk]
8.0.104 [/usr/local/share/dotnet/sdk]

.NET runtimes installed:
Microsoft.AspNetCore.App 6.0.5 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 7.0.4 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 8.0.4 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.NETCore.App 6.0.5 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 7.0.4 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 8.0.4 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]

Other architectures found:
None

Environment variables:
Not set

global.json file:
Not found

Learn more:
https://aka.ms/dotnet/info

Download .NET:
https://aka.ms/dotnet/download

Visual Studio Code Extensions

Extension	Author	Version	Folder Name
cmake-language-support-vscode	josetr	0.0.9	josetr.cmake-language-support-vscode-0.0.9
cpptools	ms-vscode	1.21.6	ms-vscode.cpptools-1.21.6-darwin-arm64
cpptools-extension-pack	ms-vscode	1.3.0	ms-vscode.cpptools-extension-pack-1.3.0
cpptools-themes	ms-vscode	2.0.0	ms-vscode.cpptools-themes-2.0.0
csdevkit	ms-dotnettools	1.11.9	ms-dotnettools.csdevkit-1.11.9-darwin-arm64
csharp	ms-dotnettools	2.48.31	ms-dotnettools.csharp-2.48.31-darwin-arm64
github-vscode-theme	GitHub	6.3.4	github.github-vscode-theme-6.3.4
kubernetes-yaml-formatter	kennylong	1.1.0	kennylong.kubernetes-yaml-formatter-1.1.0-darwin-arm64
markdown-pdf	yzane	1.5.0	yzane.markdown-pdf-1.5.0
msbuild-project-tools	tintoy	0.6.5	tintoy.msbuild-project-tools-0.6.5
platformio-ide	platformio	3.3.3	platformio.platformio-ide-3.3.3-darwin-arm64
proto	peterj	0.0.4	peterj.proto-0.0.4
swift-lang	sswg	1.11.1	sswg.swift-lang-1.11.1
vscode-commons	redhat	0.0.6	redhat.vscode-commons-0.0.6
vscode-docker	ms-azuretools	1.29.2	ms-azuretools.vscode-docker-1.29.2
vscode-dotnet-runtime	ms-dotnettools	2.1.5	ms-dotnettools.vscode-dotnet-runtime-2.1.5
vscode-edit-csv	janisdd	0.10.0	janisdd.vscode-edit-csv-0.10.0
vscode-github-actions	github	0.26.5	github.vscode-github-actions-0.26.5
vscode-icons	vscode-icons-team	12.9.0	vscode-icons-team.vscode-icons-12.9.0
vscode-lldb	vadimcn	1.10.0	vadimcn.vscode-lldb-1.10.0
vscode-pull-request-github	GitHub	0.96.0	github.vscode-pull-request-github-0.96.0
vscode-sequence-diagrams	AleksandarDev	0.4.7	aleksandardev.vscode-sequence-diagrams-0.4.7
vscode-serial-monitor	ms-vscode	0.13.1	ms-vscode.vscode-serial-monitor-0.13.1
xcode-default-theme	smockle	2.0.24	smockle.xcode-default-theme-2.0.24
xml	DotJoshJohnson	2.5.1	dotjoshjohnson.xml-2.5.1

Extension version: 2.45.25
VS Code version: Code 1.93.1 (38c31bc77e0dd6ae88a4e9cc93428cc27a56ba40, 2024-09-11T17:20:05.685Z)
OS version: Darwin arm64 23.6.0
Modes:

System Info

Item	Value
CPUs	Apple M1 Max (10 x 2400)
GPU Status	2d_canvas: enabled canvas_oop_rasterization: enabled_on direct_rendering_display_compositor: disabled_off_ok gpu_compositing: enabled multiple_raster_threads: enabled_on opengl: enabled_on rasterization: enabled raw_draw: disabled_off_ok skia_graphite: disabled_off video_decode: enabled video_encode: enabled webgl: enabled webgl2: enabled webgpu: enabled webnn: disabled_off
Load (avg)	3, 6, 7
Memory (System)	32.00GB (5.91GB free)
Process Argv	--crash-reporter-id 516dbf53-3b0c-40b9-b808-0b110887c51d
Screen Reader	no
VM	0%

A/B Experiments

vsliv368cf:30146710
vspor879:30202332
vspor708:30202333
vspor363:30204092
vscod805:30301674
binariesv615:30325510
vsaa593cf:30376535
py29gd2263:31024239
c4g48928:30535728
azure-dev_surveyone:30548225
962ge761:30959799
pythongtdpath:30769146
welcomedialogc:30910334
pythonnoceb:30805159
asynctok:30898717
pythonmypyd1:30879173
2e7ec940:31000449
pythontbext0:30879054
accentitlementst:30995554
dsvsc016:30899300
dsvsc017:30899301
dsvsc018:30899302
cppperfnew:31000557
dsvsc020:30976470
pythonait:31006305
dsvsc021:30996838
0ee40948:31013168
a69g1124:31058053
dvdeprecation:31068756
dwnewjupyter:31046869
impr_priority:31102340
nativerepl2:31139839
refactort:31108082
pythonrstrctxt:31112756
flightc:31134773
wkspc-onlycs-t:31132770
wkspc-ranged-t:31125599
ei213698:31121563

[dibarbet]

@tverboon which process is causing the high CPU usage? You may need to post the process command line string to differentiate (on Mac the C# extension processes are usually all dotnet).

Once you've identified the process, could you collect a trace of it via dotnet-trace? You can email it to me (dabarbet@microsoft.com) if you don't want to upload here.
Should be something like dotnet-trace collect -p <PID>

Thanks!

[tverboon]

It's actually Code Helper Plugin that is longer on 100%. This is not a dotnet process, so I couldn't trace it. The issue title isn't right. CPU comes down after 5 minutes. It's way slower. It seems project loading is just slower and dotnet processes seem to take longer before really start doing serious work. I am sorry, this is a horrible way to do problem solving. I created 2 video's.

Release

Release.mp4

Preview

Preview.mp4

Trace

Last part of loading trace of preview. I don't think this process is a problem at this point.

dotnet_20240925_074526.nettrace.zip

Summary

Consistent high CPU load is not the issue. Code Helper Plugin is using 100% cpu for 42 seconds in release. After this the code lense reference count is working. With the Preview release this take a little longer than 3 minutes.

[dibarbet]

@tverboon thanks, I will take a look at the trace to see if anything stands out. The Code Helper processes I believe are related to VSCode itself - however the high CPU usage in that process could be caused by an extension. I would try the following to help pinpoint if its VSCode or an extension causing the high CPU usage.

1. Disable all extensions, see if you can reproduce the issue - if so it is likely related to VSCode itself.
2. Enable just the C# extension, and see if you can reproduce the issue
3. Enable just C# + C# Dev Kit and see if you can reproduce the issue
4. If neither of those do it, keep re-enabling other extensions 1 by 1

[tverboon]

@dibarbet thanks. I will investigate the extensions tomorrow.

What do you think about the multiple attempts to load the razor files, because part of the directory path is duplicate causing files not being found? Could that be the issue why loading the projects takes much longer?

[dibarbet]

To confirm - loading projects w/ C# extension prerelease takes 3 minutes, but 42 seconds in release? And it is the same version of C# Dev Kit both times?

I wouldn't think that the Razor file loading attempts would slow down project loading, but tagging @ryzngard in case he's seen anything there. I'll need to dig into the trace to figure out more.

[tverboon]

To confirm - loading projects w/ C# extension prerelease takes 3 minutes, but 42 seconds in release? And it is the same version of C# Dev Kit both times?

Confirmed. Everything else is the same. I only switch between release and prerelease of the C# extension. Then I quit and start VSCode to start fresh.

[ryzngard]

File paths being wrong could be a bug, but I wouldn't expect it to fix over time. For the razor logs it would be a bit more helpful to enable trace logging with this config

"razor.server.trace": "Trace"

if you don't feel comfortable posting the logs on GH feel free to e-mail them to my MS address directly but please zip :)

[dibarbet]

Additionally, if you wouldn't mind collecting one more trace, but with a couple different parameters (for the slow preview version)

1. Make sure dotnet.server.trace is set to Trace
2. As soon as possible open the 'C#' output window logs to find the processId (should be near the top, and run dotnet-trace collect -p <PID> --providers Microsoft-DotNETCore-SampleProfiler - we need to capture the project loading steps to figure out what is causing it to take so long
   

And record until the 'Projects' spinner in the bottom left of VSCode stops spinning.

If you're having a hard time capturing it at the beginning, you can optionally set the dotnet.server.waitForDebugger setting which will wait 2 minutes after launching the process so you have time to start collecting the trace.

[tverboon]

@dibarbet
I ran trace collection twice. One for preview and one for release. The time before spinning stops is less than 3 minutes. It's ~1:20 for preview and ~0:40 for release. Big difference though is that release version quickly shows Codelense, but preview doesn't.

Preview

dotnet_20240926_081730.nettrace.zip

Release

dotnet_20240926_082134.nettrace.zip

[tverboon]

@ryzngard From the logging it seems that the right paths are loaded also. See attached.

5-Razor Log.1.log.zip

[dibarbet]

Thanks! Will take a look at these today.

[tverboon]

Could you find anything useful in the trace and log files?

[dibarbet]

@tverboon I did, apologies for not following up that day - I was going to ask for another trace but fell off my radar.

Interestingly there wasn't much actually happening inside the language server in either trace. It looks almost the entire difference is the server just waiting (though no indication on what it is waiting for). Likely either lock contention, or waiting on the other processes (Razor/ Devkit).

Request for the following

1. Retake the slow trace with the following command

dotnet-trace collect -p 13916 --clrevents contention+threading+perftrack+gc+gchandle+stack+threadtransfer+loader --clreventlevel informational --providers "Microsoft-DotNETCore-SampleProfiler,Microsoft-Windows-DotNETRuntime"

2. Collect a similar trace from the Razor language server - @ryzngard what is the best way to get the procces for the Razor server?

[ryzngard]

@dibarbet it looks like we don't have the PID on startup, but there is a message when the named pipe connects:

[LSP][LanguageServer.NamedPipeBasedRazorProjectInfoDriver] Connecting to named pipe {guid} on PID: {pid}

[tverboon]

@dibarbet No problem David. I know you are working really hard to improve our developer experience. It's really appreciated!

C#

dotnet_20241022_133645.nettrace.zip

Razor

dotnet_20241022_140734.nettrace.zip

@ryzngard I hope I got the right process. I couldn't find the log entry you mentioned. Also after a few seconds the start of the log file is removed. The file is growing really fast, maybe some buffer issue?

But regardless I found the process with lsof <path-to>/ms-dotnettools.csharp-2.52.24-darwin-arm64/.razor/rzls.dll This works pretty well. I assume this was the right process, otherwise I will need to try again.

[dibarbet]

But regardless I found the process with lsof /ms-dotnettools.csharp-2.52.24-darwin-arm64/.razor/rzls.dll

That seems right

Still digging into these, but the Razor trace also shows the majority of the time waiting. I suspect we may both be waiting on C# Dev Kit to send us the project information, as in the latter half of both

Unfortunately the trace doesn't seem to have recorded any of the contention events - looks like there's a difference in behavior in dotnet-trace between Mac/Windows where the clrevents are ignored in MacOS if certain providers are specified. This is an updated correct command which would show contention (though at this point I think its relatively unlikely to be contention):

dotnet-trace collect -p 32988 --clrevents contention+threading+perftrack+gc+gchandle+stack+threadtransfer+loader --clreventlevel informational --providers "Microsoft-DotNETCore-SampleProfiler"

I've also been attempting to reproduce this myself on my Mac, but unfortunately I'm not seeing major differences between different versions of the extension (loading a ~200 project sln), and no exceedingly high continued cpu usage after projects load. I assume you're still seeing both issues on the latest prerelease (2.52)?

I think the next step is to dig into the devkit processes, but I'll need to figure out the best way to capture traces of them. Additionally there is on-going work to improve startup time which we hope to have available in the next couple of releases which may help here.

[tverboon]

The trace was done with the latest prerelease. Just as before, between 2.45 and 2.52 it just takes a couple of minutes longer to get a fully functioning up to speed environment with codelens etc. This is after project loading completed.

I might have found a clue in the Razor logs that Razor ProjectService is updating Projects. This takes about 3 minutes, after that CPU usage of csharp process comes down and everything is working fast. This project updating is after the project loading spinner is gone.

[Info  - 7:46:45 AM] [LSP][LanguageServer.ProjectSystem.RazorProjectService] Updating project '/Users/tverboon/Desktop/Code/Midmid/src/Midmid.Portal/obj/Debug/net8.0/' TagHelpers (285) and C# Language Version (CSharp12).
...
...
net8.0/' TagHelpers (285) and C# Language Version (CSharp12).
[Info  - 7:49:15 AM] [LSP][LanguageServer.ProjectSystem.RazorPro

Trace of project loading.
dotnet_20241023_074508.nettrace.zip

Additionally there is on-going work to improve startup time which we hope to have available in the next couple of releases which may help here.

I also noticed Dustin Campbell is doing a lot of work around the Razor project system, maybe it's wise to wait and not chase a moving target.

This is not a show stopper for me. It just takes a little longer to load and CPU usage eventually comes down. As long as I don't have to restart VS Code during the day, it's not a big problem.

[dibarbet]

Finally was able to get back to this. Thanks for the updated trace. As expected there is some contention, but only about 0.4% of the cpu time. I was also able to reproduce this in a large Razor project (on Windows as well) using MudBlazor.

Essentially what looks to be happening is that Razor is triggering LSP didOpen/didClose for every virtual C# file and Razor file. This can block other LSP requests from running (didOpen/didClose are special here). The behavior appears to be similar in both 2.45 and later versions - however there are a couple differences-

1. In 2.45, it looks like sometimes the initial codelens/semantic tokens/diagnostics for the open files goes through before the didOpen/didClose for every file starts running. This appears to make the load look faster, even though subsequent requests get blocked by all the close and opens.
2. In 2.45, the full project load only takes ~5 minutes for me locally vs. 8 minutes in 2.56.29. All the work appears to be happening in the opening closing of Razor and virtual C# files.

Passing this on to the Razor folks - @ryzngard is there any way we can avoid sending LSP didOpen/didChanges for (what looks to be) every Razor and virtual C# file? These LSP requests completely block other LSP requests from running. Is this going to improve once we switch to the source generator for C# generation?

[tverboon]

@dibarbet Thanks for following up. Did you also notice the didOpen and didClose events with wrong paths, like I mentioned in my opening comment?

didOpen for virtualcsharp-razor:///Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web /Users/tverboon/Desktop/Code/Midmid/src/Midmid.Shop.Common.Web /Views/Shared/DisplayTemplates/EmailAddress.cshtml__virtual.cs

The correct paths are also loaded, but these wrong paths are causing extra opening and closing events. See also above: #7582 (comment)

[ryzngard]

2.60.26 was released today with the fix in. On my machine the load for MudBlazor dropped to around 2.5 minutes from a little over 5 minutes.

Thanks for the traces and reporting @tverboon !

[tverboon]

Thanks @ryzngard! On my machine our project load time is also almost cut in half. Nice work!