Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Performance: Basic Keypresses in Solution with All Analyzers Disabled Causes ServiceHub.RoslynCodeAnalysisService.exe to Utilize ~10% of CPU #54914

Closed
Mike-E-angelo opened this issue Jul 19, 2021 · 61 comments
Assignees
Labels
Area-Compilers Feature - Source Generators Source Generators Need More Info The issue needs more information to proceed.
Milestone

Comments

@Mike-E-angelo
Copy link

Mike-E-angelo commented Jul 19, 2021

Version Used: 3.8.0

Steps to Reproduce:

  1. Open this solution
  2. Note all analyzers have been disabled in all projects via <EnableNETAnalyzers>false</EnableNETAnalyzers>
  3. Ensure you are using a custom Refit nupkg which comments out this line and this line, rendering the Refit source generator as a noop
  4. Modify a file with basic key presses (e.g. Enter followed by Backspace)
  5. Observe considerable CPU churn of around 10% even though analyzers have been disabled.

Expected Behavior:
There are two issues here:

  1. When analyzers and/or live analysis are disabled, CPU utilization by ServiceHub.RoslynCodeAnalysisService.exe should be minimal if at all.
  2. When analyzers are disabled -- by build and/or by live analysis -- this should impact source generators as well, as they are registered as analyzers.

Actual Behavior:
ServiceHub.RoslynCodeAnalysisService.exe consumes a considerable amount of CPU, even when analyzers are disabled in a solution. Additionally, source code generators execute when analyzers are disabled even though they are registered as analyzers.

Additional Context:
This issue was originally reported here, and then opened as an issue on the Refit repository here.

@CyrusNajmabadi
Copy link
Member

The type model does not appear to be properly cached with each syntax notification, leading to a lot of CPU churn for larger solutions.

This is a core part of how roslyn works. When you make an edit you get an entirely fresh snapshot of the code. In that snapshot all symbols are fresh. THis is necessary for correctness as symbols point at each other and at locations. So it would be broken if GetTypeByMetadataName returned a prior symbol as that could then point at code that doesn't exist (or is in the wrong location) in the compilation currently being interrogated.

@Mike-E-angelo
Copy link
Author

Mike-E-angelo commented Jul 19, 2021

Thank you for the reply and additional context @CyrusNajmabadi. That does make sense to me and I appreciate that design. The request/ask here is to find a more efficient way to resolve the requested symbols in larger solutions so that it doesn't turn a PC into a personal space heater when the most basic of keystrokes are applied. :)

@CyrusNajmabadi
Copy link
Member

so that it doesn't turn a PC into a personal space heater when the most basic of keystrokes are applied. :)

You can see if you can get that source generator to change. I'm really not sure what we could do here in this specific Roslyn method. Note that this method is already used extensively by dozens to hundreds of roslyn services. So it's unlikely that GetTypeByMetadataName is the true problem, and is likely more an issue around whatever Refit is doing in terms of source generation.

@Mike-E-angelo
Copy link
Author

Note that this method is already used extensively by dozens to hundreds of roslyn services

And I celebrate that. However, my issue here is neither its widespread use nor its correctness but rather its apparent inefficiency which seems to present itself in obvious fashion with larger solutions.

and is likely more an issue around whatever Refit is doing in terms of source generation.

I did get a reply by @clairernovotny in this comment here which seems to imply that it is not a Refit issue. Any further comment on this would be greatly appreciated, as it seems I now have two parties that say they are not responsible for the 10-20% CPU utilization that occurs in ServiceHub.RoslynCodeAnalysisService.exe when the most basic of keypresses are applied to the IDE text editor.

Also tagging @sharwell as a lifeline here as he is the reason I am on this path in the first place. :)

@Mike-E-angelo
Copy link
Author

Alright, so I have put some more thought/investigation here. The interesting aspect is that this problem does not emerge until a Blazor server-side project is added to the solution. With no Blazor server-side project added to the solution, ServiceHub.RoslynCodeAnalysisService.exe reports 1% utilization, while with a Blazor server-side project added, the 10-20% utilization emerges.

Currently, I am using net5.0, and I know there have been numerous improvements in net6.0 with respect to Blazor class/view generation, which may be contributing to this particular issue.

So, I will close this issue for now and report back once I have installed Visual Studio 2022 and have upgraded to net6.0 for my solution.

@CyrusNajmabadi I do appreciate your patience and guidance in attempting to steer me in the right direction here. Believe it or not, I do strive to be a good citizen while figuring out all the numerous fires in my world as currently presented to me -- of which, there are so very many. :P

@Mike-E-angelo
Copy link
Author

Well apologies for the back and forth here, my curiosity got the better of me.

I decided to install Visual Studio 2022 Preview and even without a Blazor Server-side project, I was able to get the same 10-20% CPU utilization using this SLN by pressing Enter/Backspace on this file.

Looks like most of the time is spent here and here.

@Mike-E-angelo Mike-E-angelo reopened this Jul 20, 2021
@Mike-E-angelo
Copy link
Author

Mike-E-angelo commented Jul 20, 2021

A look at allocations here. dotTrace is reporting 9% of the time spent on GC Wait.

@CyrusNajmabadi
Copy link
Member

How many references are in this project?

@CyrusNajmabadi
Copy link
Member

@dotnet/roslyn-compiler two seconds in GetTypeByMetadataName does seem on the high side. What information would be helpful to diagnose if somethign is going wrong here?

@Mike-E-angelo
Copy link
Author

How many references are in this project?

Good question @CyrusNajmabadi. To be sure, the problem is not isolated to the particular file I have been using and referencing. It appears to occur with any file in the solution that I provided, which has 26 projects listed within it.

To simplify, using this file from the core project reproduces the CPU churn, and it only has 7 references in it.

@jaredpar
Copy link
Member

two seconds in GetTypeByMetadataName does seem on the high side.

For an extremely large project that doesn't seem to unrealistic. That is going to search through every reference in the Compilation and the current project. Particularly on a first call that is going to force binding and parsing of all types in the solution. Not unrealistic that for a big enough project, particularly one with a lot of source types, that it would take that long.

What information would be helpful to diagnose if somethign is going wrong here?

The best way is to get an ETL trace of the problem. Also a binary log with report analyzers enabled would quickly rule that out as a potential source of problems.

To simplify, using this file from the core project reproduces the CPU churn, and it only has 7 references in it.

That compiles in less than a second for me.

Note: it has 7 package references but under the hood it has 200 compilation references.

@jaredpar jaredpar added Need More Info The issue needs more information to proceed. and removed untriaged Issues and PRs which have not yet been triaged by a lead labels Jul 20, 2021
@Mike-E-angelo
Copy link
Author

Mike-E-angelo commented Jul 20, 2021

Thank you for your time and consideration with this issue, @jaredpar.

That compiles in less than a second for me.

The issue here is not compilation (which is indeed sufficient!), but rather syntax notifications that occur when simple keypresses such as Enter/Backspace are applied to files during editing within the IDE text editor. CPU utilization by ServiceHub.RoslynCodeAnalysisService.exe easily reaches 10-20% when using the provided file within the provided solution via the reproduction steps provided in the original post.

The best way is to get an ETL trace of the problem.

FWIW several were provided in the original ticket.

@CyrusNajmabadi
Copy link
Member

CPU utilization by ServiceHub.RoslynCodeAnalysisService.exe easily reaches 10-20%

I mentioned this before (i think), but this doesn't seem like an issue to me. It seems expected. A change was made. The generator is running and causing semantic analysis to happen. Semantic analysis is costly.

So having this consume CPU cycles is expected here. If the cost of this generator is too much, i think you'd have to turn it off.

It's possible the SG v2 api might help out here depending on what this generator is actually doing. But it will require refit to move onto that api.

@Mike-E-angelo
Copy link
Author

Semantic analysis is costly

I'm only pressing Enter/Backspace tho. 😉

So having this consume CPU cycles is expected here

Right, but 10-20%? I'm running 8-core/16-threads on a Ryzen 7 3700X as well. That simply seems really excessive for basic key presses in an IDE.

@Mike-E-angelo
Copy link
Author

Also, as I have mentioned, there are numerous fires in my world. This is only one of several identified performance monsters that I am battling. Here is what my process tree looks like by simply pressing Enter/Backspace in Visual Studio:

So, nearly half of my CPU energy is completely dedicated to processing Enter/Backspace. This seems incredibly wrong to me which is why I am making such an effort to see what can be done about it.

@RikkiGibson
Copy link
Contributor

Looks like most of the time is spent here and here.

I'm confused why this these would be prominent in your trace. Especially the second one which is commented // internal for testing.

I'm curious about what's happening in this scenario so I will try to make some time to check out the trace as well. I'll let you know if I spot anything worth calling out in it.

@Mike-E-angelo
Copy link
Author

Thank you @RikkiGibson! Any assistance/consideration you can lend is very much appreciated. 🙏

@CyrusNajmabadi
Copy link
Member

I'm only pressing Enter/Backspace tho.

Every keystroke requires full analysis :)

@CyrusNajmabadi
Copy link
Member

Right, but 10-20%? I'm running 8-core/16-threads on a Ryzen 7 3700X as well. That simply seems really excessive for basic key presses in an IDE.

It sounds reasonable to me. Effectively, all analysis has to be redone. We don't know what the analyzer will be doing and all our information has to be accurate for any questions it makes.

Like i said before though, the v2 api might help here as it may enable this analyzer to opt out of being run in cases it doesn't care about.

@Mike-E-angelo
Copy link
Author

Like i said before though, the v2 api might help here as it may enable this analyzer to opt out of being run in cases it doesn't care about.

👍

I also have an outstanding question back on the Refit issue on why syntax notifications are used rather than performing the processing on compilation. It would be nice if we could change the behavior via configuration setting somehow.

@jaredpar jaredpar added the Feature - Source Generators Source Generators label Jul 21, 2021
@jaredpar jaredpar added this to the 17.0 milestone Jul 21, 2021
@Mike-E-angelo
Copy link
Author

Mike-E-angelo commented Jul 21, 2021

I mean... this is literally our server which does things like computing diagnostics for your solution, as well as all these features (and more):

I know CodeLens can be turned off, but what about the others? In addition to most of these features already provided by R#, it would be valuable to be able to toggle these features on and off to see if any of them are causing the grief here (a quick search in VS options didn't turn up anything obvious except for codelens).

Can you perform the steps here to record and submit a trace: main/docs/wiki/Reporting-Visual-Studio-crashes-and-performance-issues.md

Sure thing @CyrusNajmabadi here you go:
https://developercommunity.visualstudio.com/t/performance-basic-keypresses-in-solution-with-all/1481034

Please do let me know if I overlooked something and/or you require more information.

Otherwise, thank you again for the spirited and informative discussion. It is very much appreciated. ✨

@Mike-E-angelo
Copy link
Author

Oh, there is one more point I wanted to make, after reviewing the original issue.

While 10% "seems" nominal (although I am not entirely convinced, obviously), the original reporting had ServiceHub.RoslynCodeAnalysisService.exe consuming much much more. Here is an example of 56.8%, and another at 27%.

Both of these occurred after the IDE had been opened for some time.

Now that I have a better layout of the land here and can disable necessary components, I will keep an eye open for these higher readings and provide you better telemetry if/when it occurs. 👍

@CyrusNajmabadi
Copy link
Member

As above, we would need traces to investigate this.

@Mike-E-angelo
Copy link
Author

To clarify @CyrusNajmabadi you should have multiple traces already provided and available to you in the original issue. However, they have the source generator enabled.

What I was suggesting was that I would be able to provide better traces going forward now that I have a better understanding of what is happening.

@CyrusNajmabadi
Copy link
Member

right. i'm saying: we'd need traces without hte SG running to see if there is anything amiss here, or if this is just normal and expected behavior. Thanks!

@CyrusNajmabadi
Copy link
Member

I know CodeLens can be turned off, but what about the others? In addition to most of these features already provided by R#, it would be valuable to be able to toggle these features on and off to see if any of them are causing the grief here (a quick search in VS options didn't turn up anything obvious except for codelens).

Most cannot. People want colors/highlighting. We want our indices to be up to date so that FindRefs/NavTo is fast. We want live errors in the IDE. We want lightbulbs. Etc. etc.

What you are describing is simply that we are doing work when edits happen. As above, this is just expected. We have a lot of features/analysis that lights up, and using the CPU to compute this is really the purpose of using an IDE.

Here is an example of 56.8%, and another at 27%.

Neither of these seem weird. And we'd need traces to know if there was actually an issue. What matters is how much sustained CPU we use, and for how long, and if that is out of line for that particular feature. For example, many features are designed to operate concurrently to actually complete more quickly. We often attempt to scale up with cores precisely so that you can make good use of hte "Ryzen 7 3700X" you have :)

@Mike-E-angelo
Copy link
Author

People want colors/highlighting. We want our indices to be up to date so that FindRefs/NavTo is fast. We want live errors in the IDE. We want lightbulbs

"We" might but others already have that covered. :) It seems like it would be valuable to be able to toggle these on/off to not only preserve system taxation but to also help diagnose situations such as these.

Neither of these seem weird.

Haha sorry we will never agree that over 50% of the CPU is necessary to process simple Enter/Backspace commands. Notepad++ does it in .5% (yes, a totally fair comparison 😅) and R# is also clocking in the 10% range.

Which, btw, I am very very familiar with how much developers typically complain about R# overhead/performance -- and in fact, refuse to use it due to such concerns. At 10% utilization/drain ServiceHub.RoslynCodeAnalysisService.exe is basically hovering in the same taxation department now as R# now. Food for thought.

For example, many features are designed to operate concurrently to actually complete more quickly.

I understand but that is also my concern. With a 4-core we're saying 20% of total CPU is being used by ServiceHub.RoslynCodeAnalysisService.exe alone. I am running my development environment on Hyper-V and am able to confirm this. That's why I make mention of the Ryzen because there is so much horsepower there. 10% with such a resource is not a good thing, IMO. It "seems" nominal but deceptively so.

@CyrusNajmabadi
Copy link
Member

CyrusNajmabadi commented Jul 21, 2021

Haha sorry we will never agree that over 50% of the CPU

I'm sorry, but i don't think we're going to change in that regard. Frankly, i would prefer we get up to 100% (albeit with a low pri process such that other interactive tasks on the system are unimpacted). We have multicore machines and facilitating getting results back to the user as quickly as possible is a key design goal here. Limiting our usage to some arbitrary low percentage doesn't seem sensible**

10% with such a resource is not a good thing,

I genuinely do not understand the argument there :). Percentage isn't something that matters. After all, the more concurrent and decoupled we make things, the easier it will be for us to just hit 100% as we scale up. What matters is total aggregate CPU usage and if that is out of line for a particular feature (or set of features).

--

** One area where it would make sense is battery operated devices where longevity of unplugged time is a valued resource. However, for normal desktop usage this would not apply.

@Mike-E-angelo
Copy link
Author

I'm sorry, but i don't think we're going to change in that regard

Apology accepted. 🙃

Percentage isn't something that matters

I get what you're saying. In my view, it's a metric, basically. I'm not sure the typical developer has my type of hardware. Is my hardware typical? I mean, I am so focused on code and reporting problems I am not too aware of the typical setup these days. If the typical developer these days is working with 8-cores, then 10% does "seem" nominal. But if the typical developer has a 4-core system, does 20% sustained CPU utilization while typing "seem" OK? To me, that seems a little excessive.

the easier it will be for us to just hit 100% as we scale up

We may be running into a disconnect here. 100% is not a goal/destination and in fact should be avoided. At 50% CPU utilization my room temperature increases by 4-degrees. I would hate to see 100% consistently applied to my machine and would raise an eyebrow towards any process that does... and probably find a way to uninstall it. :P

@Mike-E-angelo
Copy link
Author

BTW, doing a simple test here. The w/ Enter/Backspace a typical .cs file, devenv.exe:

With R# disabled: 1.5-2.5%
With R# enabled: 9-10%

So R# overhead is currently ~7.5% in this scenario while ServiceHub.RoslynCodeAnalysisService.exe is ~10%, or 25% more net total utilization than R#. Maybe not a 100% apples-to-apples comparison, but with as much complaining that I have heard over the years regarding R# performance, I find that both striking and maybe a little hilarious. :)

@PathogenDavid
Copy link
Contributor

I'm not sure the typical developer has my type of hardware.

You should let people with old hardware worry about problems affecting their old hardware rather than assuming these issues exist.

My daily driver still uses an i7-4770 from 2013. I have Code Lens as well as solution-wide background analysis enabled, I regularly work in huge solutions and huge files, and I'm absurdly impatient person when it comes to computers. My startup performance isn't always the best, but I do not have issues any issues with typing performance outside of utterly massive files.

As Cyrus said, percentages don't really mean anything. With your "test" on my machine, the analysis service only reaches 17% at most (usually 9-12%) and my CPU doesn't even reach its maximum clock rate. Don't worry about performance issues in theory, worry about performance issues in practice.

The fix for this issue is to stop staring at Task Manager while you're typing.

@Mike-E-angelo
Copy link
Author

but I do not have issues any issues with typing performance outside of utterly massive files.

Lucky, try breaking out some .razor files in net5.0 and let me know how you fare.

With your "test" on my machine, the analysis service only reaches 17% at most (usually 9-12%)

So again the problem before I originally reported it is that CPU was reaching over 50% with the same "test" after the IDE had been open for a while... the seemingly benign condition points to a more involved issue, is my driving point here. Honestly, if it was 10% I probably wouldn't have noticed as I have other outstanding issues that utilize more. However, when there are obvious hitching/chunking/delays of characters emitted on the screen along with a buffet of GC it's time to take a look into it.

The fix for this issue is to stop staring at Task Manager while you're typing.

Funny enough I wasn't even paying attention to Task Manager until I noticed it was taking several seconds between keypresses on the hardware to actually translating on-screen. That is when I started paying attention to what Task Manager had to say.

I have been fighting several major performance issues throughout Visual Studio for the past 6 months at least, with a good deal of them being related to Blazor. Turns out there are several other gremlins that are tagging along for the ride and this is one of them.

@PathogenDavid
Copy link
Contributor

So again the problem before I originally reported it is that CPU was reaching over 50%

Then why are you derailing your own thread whingeing on about that 10%?

However, when there are obvious hitching/chunking/delays of characters emitted on the screen[...]

[...]until I noticed it was taking several seconds between keypresses on the hardware to actually translating on-screen.

Out of the three places you've posted this issue (and I'm pretty sure all of your comments on them), you haven't mentioned this in any of them. There's a huge difference between getting bent out of shape over your task manager and having your productivity impacted by keyboard lag.

@CyrusNajmabadi
Copy link
Member

but with as much complaining that I have heard over the years regarding R# performance, I find that both striking and maybe a little hilarious. :)

This is a misrepresentation. the issues with Resharper perf in the past deal with UI delays and excessive memory usage (causing the VS process to run out of address space). These were issues because of the negative impact on other systems.

@CyrusNajmabadi
Copy link
Member

However, when there are obvious hitching/chunking/delays of characters emitted on the screen along with a buffet of GC it's time to take a look into it.

Can you please open a new issue on this, along with traces of when this happens? Any delay of characters to screen is something we need to look at asap and fix.

Thanks!

@Mike-E-angelo
Copy link
Author

Then why are you derailing your own thread whingeing on about that 10%?

Let's please keep this constructive. I am working with Microsoft professionals to further explore a baseline metric while getting better familiar with several interacting components to determine the root cause for a perceived performance issue.

Out of the three places you've posted this issue (and I'm pretty sure all of your comments on them), you haven't mentioned this in any of them

I am feeling a bit of hostility and being attacked here with your tone, @PathogenDavid.

Can you please open a new issue on this, along with traces of when this happens?

The traces I have already provided demonstrate this. I am literally recording what is happening on my PC and reporting it to the Visual Studio team via the Feedback Tool. My assumption in such matters has been that hitching/GC/delays are found in the recordings. Apologies if I have this misunderstood. After all, I am (painfully 😁) learning how these numerous interconnected systems work in my attempt to improve MSFT software while attempting to, you know, develop my own.

That stated, let's please keep in mind my intentions here: I am wanting to improve this product. Believe it or not, I do want to spend my days developing software rather than having to combat opinions and discussions on GitHub... even if it is fun to partake every once and a while. :)

You are more than welcome to review the existing traces as @sharwell already has done to better determine and locate what may be contributing to this. Perhaps now that we've have had an extensive conversation here new observations can be had. Please connect with him with any questions. In the meantime, as previously agreed when I see this issue occur again knowing what I know now I hope to provide even better tracing/recordings for you. 👍

@Mike-E-angelo
Copy link
Author

On every keystroke these get rerun.

FWIW I have created a feature request for Roslyn Feature Toggle here:
https://developercommunity.visualstudio.com/t/Allow-Rosyln-Features-to-be-Toggled/1482205?space=8

Thank you for any consideration. 🙏

@Mike-E-angelo
Copy link
Author

Mike-E-angelo commented Jul 22, 2021

Closing this issue now as the next step is a new recording for developercommunity. As disjointed as this was, I greatly appreciate the opportunity to work with you through this, @CyrusNajmabadi. I am equipped with more knowledge and recourse available to me now than when I started this issue, and for that I am grateful.

@Mike-E-angelo
Copy link
Author

OK @CyrusNajmabadi I believe I have figured this out for you.

Recall that I said that there appeared to be high CPU utilization after using the IDE for some time.

Well, that's part of it. After using the IDE for some time, lots of files are typically opened, and this appears to be the issue at play here. The more files that are opened, the more CPU is utilized. This does seem natural, but in my estimation, the results here with ServiceHub.RoslynCodeAnalysisService.exe seem excessive and warrant further investigation.

After opening approximately 50 files, every keypress will get my CPU as high as 33% via ServiceHub.RoslynCodeAnalysisService.exe alone, and additionally will take about 10 seconds to wind down after the last keypress.

So not only does it seem 3x the expected "normal" CPU utilization that we've discussed, but the amount of time to wind down also seems impacted as well.

Closing all but one file will return to the 10% (and quick wind down) that we have discussed (and I now expect).

I have made a recording of this for your review here:
https://developercommunity.visualstudio.com/t/ServiceHubRoslynCodeAnalysisServiceex/1482376

For the ETL recording, ReSharper was not enabled. However, to give a comparison, I have enabled R# to demonstrate the difference between the two:

https://i.imgur.com/XY9WGsO.gif

You can see that devenv.exe (where R# is running) hits a high of 17.5% but quickly throttles down, while ServiceHub.RoslynCodeAnalysisService.exe continues to chug for quite some time afterward.

Finally, note that R#-enabled devenv.exe reaches a high of 7.5% when only 1 file is opened. So, with 50 files opened there is roughly a 10% performance hit with R# (with quick wind-down). This seems acceptable/expected to me.

@CyrusNajmabadi
Copy link
Member

and additionally will take about 10 seconds to wind down after the last keypress.

That does not seem at all strange or out of the ordinary. After you type everything spins up and analyzes all the open documents. Taking 10 seconds to process 50 open docs in no way seems out of the ordinary.

@CyrusNajmabadi
Copy link
Member

seem excessive

Neither 33% utilization nor 10 seconds seems excessive tbh. As mentioned before, depending on how much decoupling we can get, we could get that up to 100% in the future (with around 3 seconds usage after your last keystroke). This seems entirely fine to me.

@Mike-E-angelo
Copy link
Author

I appreciate your continued assistance and dialogue over this, @CyrusNajmabadi.

with around 3 seconds usage after your last keystroke

We are in agreement here that a 3-second CPU wind down seems appropriate and should be an acceptable goal. I'm even warming up to your 10% minimal CPU expenditure, in much the same way that ServiceHub.RoslynCodeAnalysisService.exe continually warms up my room with all its required CPU heat when many files are opened. 😅

Neither 33% utilization nor 10 seconds seems excessive tbh

Sounds like we have a difference of opinion here. It's a hard sell for me to say that you are OK being twice as slow and resource-intensive as R# in this scenario, especially when it's nearly comparable with R# when only 1 file is opened.

Subjective excessiveness aside, perhaps we should focus on if this behavior is expected, hence the ELT/report. 👍

@Mike-E-angelo
Copy link
Author

Mike-E-angelo commented Jul 23, 2021

Alright, @CyrusNajmabadi I have some further information for you:

  1. Open this solution
  2. Expand the DragonSpark.Application project so that the DragonSpark.Application/Security/Identity/Profile namespace is visible.
  3. Open all the visible files with Right-click -> Open (this is about 60 of them):
  4. Open this file, pressing Enter at this line
  5. Observe CPU usage and time
  6. Now repeat step 3 <-- Triggering Event
  7. Repeat step 4
  8. Repeat step 5

On step 5, this is what I see with ServiceHub.RoslynCodeAnalysisService.exe:
CPU time: ~6 seconds
CPU max: ~6%
✅ Acceptable/expected

On step 8, this is what I see:
CPU time: ~13 seconds
CPU max: ~33%
❌ Different/Unexpected

So, it would indeed seem that Roslyn can handle many open files at once, after all. Nice work over there. :) However, there rather appears to be some sort of double-registration or other bug occurring between Visual Studio and Roslyn when re-opening the same files and/or opening files that are already opened. The above is (luckily) a very straightforward reproduction of the issue that I have been experiencing, but I can painfully attest that there must be another trigger that occurs during extended development that invokes it as well.

For your convenience, I have recorded the above from start to finish for your review here:
https://developercommunity.visualstudio.com/t/ServiceHubRoslynCodeAnalysisServiceex/1482376#T-N1485555

@Mike-E-angelo
Copy link
Author

I wanted to briefly check in with this issue as there has been continuing development and exploration on what the heck is happening here.

First off, I wanted to share my appreciation for this thread and its discussion. I know it got messy, and while I didn't appreciate @PathogenDavid's sharp feedback at the time, in hindsight he was right: I sort of stepped in it here.

(hey, I had just got back from some time off at the time and was not exactly in GitHub Battle Mode shape 😅)

But, that's ok, I learned a lot. And I am still learning. I appreciate your patience while I climb onto the same level as you all. As I hope to demonstrate below, there are a lot of pieces here.

And hey, if we ultimately find a gremlin (or two) that is degrading performance of your product, then worth it, right?

OK, so... getting back to the original heart of the thread, which was that a source generator (Refit) seemed to be going crazy, and it may or may not be due to ServiceHub.RoslynCodeAnalysisService.exe. I have upgraded to Visual Studio 2022 Preview 3.1 with the .NET6 SDK RC1 bits, with my solution upgraded to net6.0.

Sure enough, after some time (many hours) of development, I noticed that my CPU was getting a little more active than I expected and had even noticed earlier during that same development session. So, I took a peek with dotTrace. Here is what I saw:

Indeed, it sure seems like Refit is having a, uh, fit. 😁 But, looking closely, now that we are in net6.0, you can see that JsonSourceGenerator is also present in the CPU time as well. In fact, there's also a LoggerMessageGenerator in for the ride, with the top 3 call trees being ascribed to source generators.

Well, on a hunch, I closed my SLN and opened a new Visual Studio 2022 process. This is what I saw with that same activity as performed above in the new IDE session:

Notice the difference? Everything looks super clean and expected when opening with the brand new Visual Studio 2022 process, with none of the source generators taking nearly any of the time of the previous first grab.

So it would seem that much like this issue, there is something funny happening with the ServiceHub.RoslynCodeAnalysisService.exe process over time (or is simply triggered by as of yet-unknown process) that seems to degrade its performance and thusly impacts all source generators (not just Refit).

This has been reported here for your review:
https://developercommunity.visualstudio.com/t/Roslyn-Degrades-over-Time-Placing-Press/1508373

@sharwell
Copy link
Member

sharwell commented Aug 19, 2021

@Mike-E-angelo note that a change was just merged to Refit (reactiveui/refit#1216) that should correct the CPU overhead when used from Visual Studio 2022.

@sharwell
Copy link
Member

@Mike-E-angelo for the images in #54914 (comment), which specific files were opened? The .etl.zip files attached to the new issue ran past their buffer limits during recording, which caused a large number of samples to be removed from the report and/or assigned to the wrong stacks. I'm concerned that this may have resulted in misleading analysis results. I'm seeing evidence of a small difference in performance, but not more than 50%.

@Mike-E-angelo
Copy link
Author

note that a change was just merged to Refit (reactiveui/refit#1216) that should correct the CPU overhead when used from Visual Studio 2022.

Very cool @sharwell thank you for letting me know. To be sure, I was not encountering an issue with Refit until extensive IDE usage, but I would be interested in seeing how this impacts further usage nonetheless. I appreciate all the effort over there. 👍

for the images in #54914 (comment), which specific files were opened?

With the first ETL, I had a lot of files opened at one point, as I had been developing in that instance for over a day. When I noticed the churn, I closed all the files with the exception of 2 pinned files at the time and did the dotTrace session, which is the screenshot you see here and in the developercommunity report.

I then opened another instance of devenv.exe and did the same. It, too, also had two files pinned at the time. So, in both instances, they had 2 files pinned. At the time, I didn't think much of it but perhaps I should have tried closing all files just to be sure.

The .etl.zip files attached to the new issue ran past their buffer limits during recording

How does this happen and how do I avoid this from happening in the future? I am almost wanting to start attaching dotTrace/dotMemory files to my reports as there always seems to be something going awry with the developercommunity recordings/captures that I send. :P

@sharwell
Copy link
Member

sharwell commented Aug 19, 2021

How does this happen and how do I avoid this from happening in the future?

It can be caused by many different things. In this case, the problems may have been exacerbated by having two copies of Visual Studio open together (both with a solution open), plus two copies of Timeline64 running. The easiest way to reduce the profiling load is to close unrelated "busy" applications prior to profiling.

During my own work, I find it tedious to close applications, so I tend to instead launch the profiler manually using a bunch of modified settings (mostly this General Purpose scenario but with greatly increased buffer sizes). I also have a large amount of memory and extremely fast storage so it makes it a bit easier to get away with sub-optimal measurement conditions. :)

I am almost wanting to start attaching dotTrace/dotMemory

This tends to cause problems. The presentation is different than we're used to seeing, so problems tend to get lost in the details. It also doesn't data we rely on from the feedback tool for accuracy. The workflow and automation are built entirely around the primary expected data, and even small deviations can mean the difference between getting a fix and getting Closed - Lower Priority.

@Mike-E-angelo
Copy link
Author

OK you are in luck @sharwell I am encountering that issue now after basically closing the previous solutions after creating that report. I have recorded/posted another session. Let's hope it's better. 🤞

One thing that I have noticed is that when I start the recording, the recorded VS instance freezes and I have to Pause Recording, Resume Recording to get it to actually start recording. Even then it takes about 5 seconds to kick in. I am not sure if that is part of the problem here but it's worth mentioning.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Area-Compilers Feature - Source Generators Source Generators Need More Info The issue needs more information to proceed.
Projects
None yet
Development

No branches or pull requests

7 participants