search

dotnet / vscode-csharp

Official C# support for Visual Studio Code
MIT License
2.87k stars 676 forks source link

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

Open tverboon opened 1 month ago

tverboon commented 1 month ago

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 commented 1 month ago

@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 commented 1 month ago

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

https://github.com/user-attachments/assets/b39948a6-6a8e-48f7-afff-5421095a2350

Preview

https://github.com/user-attachments/assets/5e8bb012-ff9d-4a8e-9d78-545b27c65a58

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 commented 1 month ago

@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 commented 1 month ago

@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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 image

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 commented 1 month ago

@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 commented 1 month ago

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

5-Razor Log.1.log.zip

dibarbet commented 1 month ago

Thanks! Will take a look at these today.

tverboon commented 3 weeks ago

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

dibarbet commented 3 weeks ago

@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 commented 3 weeks ago

@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 commented 3 weeks ago

@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 commented 3 weeks ago

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 commented 3 weeks ago

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 commented 2 days ago

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 commented 2 days ago

@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: https://github.com/dotnet/vscode-csharp/issues/7582#issuecomment-2376052998