Performance made me disable the extension

[Rand-Random]

I love the idea, and jumped the gun when I read the devblogs page. https://devblogs.microsoft.com/visualstudio/experimental-msbuild-editor/

But, sadly the performance opening a csproj made me disable the extension (for now). Its hard to swallow when you need to adjust settings for all csproj files and are forced to wait 8+ seconds for each csproj file.

So, I hope someday only opening a csproj won't cause this performance drag.

If this is a unknown problem, and I can help figure it out the issue, I can provide further information, if you tell me what you need.

[KirillOsenkov]

Are you sure this extension is at fault? Have you profiled?

[Rand-Random]

Didn‘t profile it, but 1) Visual Studio’s yellow bar of doom is saying the extension cause a 8 sec delay 2) disabling the extension fixed the problem

and yes, it happens every time, so easy to reproduce. If you tell me what the preferred way to profile is, I can provide a profile session.

[KirillOsenkov]

You can do Help -> Report a Problem, it has a way to record a trace (from a different VS instance), then send us a link to the developer community ticket that gets created

[Rand-Random]

Here you go: https://developercommunity.visualstudio.com/t/MSBuildEditor-extension-causes-a-8-seco/10690601?port=1025&fsid=a5298636-6a2c-4c28-a539-5830b00f8e9f

Created this profile with a blank .net 8 console application.

[KirillOsenkov]

hi, unfortunately it doesn't look like we have any data from you, have you clicked Start Recording?

the instructions are here: https://learn.microsoft.com/en-us/visualstudio/ide/how-to-report-a-problem-with-visual-studio?view=vs-2022

[Rand-Random]

Yes, I did, even waited for the process to complete even though it said, I could already close visual studio and submit the issue. Though, sadly not the first time I was told it didn't upload correctly.

But let me try again... same issue as before, added a comment with the recording hopefully intact this time around here a screenshot of the claimed successfull upload

[Rand-Random]

Can you verify if the recordings are now available to you?

[KirillOsenkov]

@davkean

[davkean]

The recordings are available, thanks. Unfortunately, Windows didn't send us CPU samples (do you have hyper-V installed?), so we might have trouble.

Make note I know nothing about how these pieces play together so below is a "guess" based on what I see in the trace.

The following stack is hanging the UI thread for 8 seconds, here ReSharper is asking the editor for the lightbulb actions from the extension. MonoDevelop.MSBuildEditor is incorrectly calling Task.Wait on UI thread, which we will come to in a second.

Name
 ||            ||||||||   |||||  ||||||    | |      |         + JetBrains.PsiFeatures.VisualStudio.SinceVs14!JetBrains.PsiFeatures.VisualStudio.SinceVs14.LightBulbs.VsLightBulbAdapter14+<<GetSuggestedActions>b__11_0>d.MoveNext()
 ||            ||||||||   |||||  ||||||    | |      |          + JetBrains.PsiFeatures.VisualStudio.SinceVs17!VsLightBulbAdapter17.GetTopLevelActionSetsAsync
 ||            ||||||||   |||||  ||||||    | |      |          |+ mscorlib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[System.__Canon].Start(!!0&)
 ||            ||||||||   |||||  ||||||    | |      |          | + JetBrains.PsiFeatures.VisualStudio.SinceVs17!JetBrains.PsiFeatures.VisualStudio.SinceVs17.LightBulbs.VsLightBulbAdapter17+<GetTopLevelActionSetsAsync>d__5.MoveNext()
 ||            ||||||||   |||||  ||||||    | |      |          |  + JetBrains.PsiFeatures.VisualStudio.SinceVs14!VsLightBulbAdapter14.RunWithTimeout
 ||            ||||||||   |||||  ||||||    | |      |          |   + JetBrains.PsiFeatures.VisualStudio.SinceVs17!JetBrains.PsiFeatures.VisualStudio.SinceVs17.LightBulbs.VsLightBulbAdapter17+<>c__DisplayClass5_0.<GetTopLevelActionSetsAsync>b__0(value class JetBrains.Lifetimes.Lifetime)
 ||            ||||||||   |||||  ||||||    | |      |          |    + mscorlib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[System.Collections.Immutable.ImmutableArray`1[System.__Canon]].Start(!!0&)
 ||            ||||||||   |||||  ||||||    | |      |          |     + JetBrains.PsiFeatures.VisualStudio.SinceVs17!JetBrains.PsiFeatures.VisualStudio.SinceVs17.LightBulbs.VsLightBulbAdapter17+<>c__DisplayClass5_0+<<GetTopLevelActionSetsAsync>b__0>d.MoveNext()
 ||            ||||||||   |||||  ||||||    | |      |          |      + mscorlib.ni!RuntimeMethodInfo.Invoke
 ||            ||||||||   |||||  ||||||    | |      |          |       + mscorlib.ni!RuntimeMethodInfo.UnsafeInvokeInternal
 ||            ||||||||   |||||  ||||||    | |      |          |        + clr!RuntimeMethodHandle::InvokeMethod
 ||            ||||||||   |||||  ||||||    | |      |          |         + clr!CallDescrWorkerReflectionWrapper
 ||            ||||||||   |||||  ||||||    | |      |          |          + clr!CallDescrWorkerWithHandler
 ||            ||||||||   |||||  ||||||    | |      |          |           + clr!CallDescrWorkerInternal
 ||            ||||||||   |||||  ||||||    | |      |          |            + microsoft.visualstudio.platform.vseditor.ni!LightBulbSession.PopulateWithDataAsync
 ||            ||||||||   |||||  ||||||    | |      |          |             + microsoft.visualstudio.platform.vseditor.ni!LightBulbSession.TryGetSuggestedActionSets
 ||            ||||||||   |||||  ||||||    | |      |          |             |+ microsoft.visualstudio.platform.vseditor.ni!LightBulbSession.QuerySuggestedActions
 ||            ||||||||   |||||  ||||||    | |      |          |             | + mscorlib.ni!System.Collections.Generic.List`1[System.__Canon].InsertRange(Int32, System.Collections.Generic.IEnumerable`1)
 ||            ||||||||   |||||  ||||||    | |      |          |             | |+ MonoDevelop.Xml.Core!MonoDevelop.Xml.Logging.LoggerExtensions+LoggedEnumerable`1+LoggedEnumerator[System.__Canon].MoveNext()
 ||            ||||||||   |||||  ||||||    | |      |          |             | ||+ MonoDevelop.MSBuild.Editor!MonoDevelop.MSBuild.Editor.Analysis.MSBuildSuggestedActionSource+<GetSuggestedActionsInternal>d__11.MoveNext()
 ||            ||||||||   |||||  ||||||    | |      |          |             | || + MonoDevelop.MSBuild.Editor!TaskExtensions.WaitAndGetResult

On a background thread, I see that it takes about 2 seconds to parse the MSBuild file:

Name
 || | ||        || + mscorlib.ni!ExecutionContext.Run
 || | ||        ||  + mscorlib.ni!ExecutionContext.RunInternal
 || | ||        ||   + mscorlib.ni!Task.Execute
 || | ||        ||    + mscorlib.ni!System.Threading.Tasks.Task`1[System.__Canon].InnerInvoke()
 || | ||        ||     + MonoDevelop.MSBuild.Editor!MonoDevelop.MSBuild.Editor.Completion.MSBuildBackgroundParser+<>c__DisplayClass10_0.<StartOperationAsync>b__0()
 || | ||        ||     |+ MonoDevelop.MSBuild!MSBuildRootDocument.Parse

The background thread is then blocked on the following for 6 seconds trying to get to the UI thread via JTF. It will never be given the UI thread because the Task.Wait blocked on the UI thread does not pump JTF messages.

Name
 || | ||        || | |       + MonoDevelop.Xml.Editor!MonoDevelop.Xml.Editor.Parsing.BackgroundProcessor`2+<>c[System.__Canon,System.__Canon].<CreateOperation>b__2_0(class System.Threading.Tasks.Task`1,class System.Object)
 || | ||        || | |        + MonoDevelop.MSBuild.Editor!MSBuildBackgroundParser.OnOperationCompleted
 || | ||        || | |         + ?!?
 || | ||        || | |          + MonoDevelop.MSBuild.Editor!MSBuildValidationTagger.ParseCompleted
 || | ||        || | |           + microsoft.visualstudio.threading.ni!JoinableTaskFactory.Run

I suspect (but cannot confirm) that ReSharper is passing a cancellation token that expires after 8 seconds, if it didn't do that, this would never recover and hang forever.

The fix in this code base would be to change WaitAndGetResult to JoinableTaskFactory.Run(task). This will give the last stack permission to switch to the UI thread, however, the product will still hang for 2 seconds because it takes that long to parse the file, so how these action sets are produced probably needs to be rethought. Its unclear to me, and we'd need to pull in editor folks to confirm, if we expect ReSharper to be asking for the lightbulb actions at this time. Even still that Task.Wait should be replaced with JoinableTaskFactory.Run.

[KirillOsenkov]

Thanks for looking, really appreciate it!

[Rand-Random]

@davkean

Unfortunately, Windows didn't send us CPU samples (do you have hyper-V installed?), so we might have trouble.

No

BUT if I remember correctly it was previously installed, atleast the manager to remote connect to a hyper-v server, but my machine is a local machine and not a virtual one. I had to uninstall it (again if I remember correctly) when I upgraded to Windows 11 because of the whole TPM requirement thing.

[Rand-Random]

@KirillOsenkov Since the proposed solution seems to be a one-liner, can you give a time frame when I could expect a new version with this fix?

[KirillOsenkov]

No timeline but we'll try to get to it when we can. Thanks.