Solution with 56 projects is unsable once migrated to csproj.

NTaylorMullen commented 7 years ago

Every major operation (opening/restoring, building, etc.) takes several minutes to complete, usually resulting in the "not responding" dialog over and over. As a disclaimer the project does take more time than average project to restore but it should not repeatedly dive into the "not responding" state or take as long as it currently does. Doing these operations at the command line is significantly faster.

This branch of MVC demonstrates the issue quite well. Note, it used to work decently fine with the xproj system.

The VS I'm using:

NTaylorMullen commented 7 years ago

Updated issue with additional info.

mavasani commented 7 years ago

Open solution

I tried opening the solution on D15PreRel 26130 and it takes:

Slightly less than 60 seconds to fully load the solution in a new VS instance.
Closing and re-opening the solution in the same VS instance takes roughly 35-40 seconds to load.

IMO, these seem like pretty reasonable load times for a 50+ project solution. Did you see something different @NTaylorMullen ? Only VS component that takes up significant amount of time (20%-30%) is microsoft.visualstudio.projectsystem.implementation!PropertyPagesCatalogLoader.CreatePropertyCatalogsAsync, we can ask CPS folks to look if that can be optimized.

Build/Restore

I am unable to restore the solution from command line or VS (build.cmd fails). Migration fails for one of the projects, which is probably the cause of this:

Microsoft.AspNetCore.Mvc.FunctionalTests

Message

test\Microsoft.AspNetCore.Mvc.FunctionalTests\Microsoft.AspNetCore.Mvc.FunctionalTests.xproj: Failed to migrate XProj project Microsoft.AspNetCore.Mvc.FunctionalTests. 'dotnet migrate --skip-backup -s -x "c:\Mvc\test\Microsoft.AspNetCore.Mvc.FunctionalTests\Microsoft.AspNetCore.Mvc.FunctionalTests.xproj" "c:\Mvc\test\Microsoft.AspNetCore.Mvc.FunctionalTests" -r "C:\Users\mavasani\AppData\Local\Temp\f4cmfz05.xwr" --format-report-file-json' exited with error code 1.

test\Microsoft.AspNetCore.Mvc.FunctionalTests\Microsoft.AspNetCore.Mvc.FunctionalTests.xproj: MIGRATE1014::Unresolved Dependency: Unresolved project dependency (MvcSandbox)

Can you try to open/migrate/build your solution on latest d15prerel? Additionally, if you can collect the perfview ETL traces for the scenarios where you get the UI hang, that would help investigations going quicker:

Download PerfView from https://www.microsoft.com/en-us/download/details.aspx?id=28567
Start VS and execute your scenario till you see the high CPU usage.
In PerfView, click Collect -> Collect -> Start Collection (note the location where the trace is collected)
Wait for few seconds for the trace collection
Stop Collection in PerfView
Share the ETL trace generated by PerfView - Let me know once you have a trace and I can provide you a onedrive link to upload it or you can put it on an internal share.

mavasani commented 7 years ago

Restore in VS generates this error:

Error occurred while restoring NuGet packages: The operation failed as details for project Microsoft.AspNetCore.Mvc.RazorPages.Test could not be loaded.

Eilon commented 7 years ago

@mavasani you mention that migration failed, but this solution is already 100% CSPROJ. Which migration was it?

NTaylorMullen commented 7 years ago

@mavasani ensure you checkout the nimullen/migration.badvs branch I mentioned in the issue and then open the Mvc.sln. I had to manually migrate a lot of MVC due to its complexity/known bugs in dotnet migrate.

mavasani commented 7 years ago

Yes, I did that and the build succeeded. Thanks, investigating further.

mavasani commented 7 years ago

Alright, so I got a VS hang when attempting to open the solution from your branch. The hang is coming from PropertyBrowser forcing certain property to be computed on the UI thread:

    mscorlib.dll!System.Threading.Monitor.Wait(object obj, int millisecondsTimeout, bool exitContext)   Unknown
    mscorlib.dll!System.Threading.Monitor.Wait(object obj, int millisecondsTimeout) Unknown
    mscorlib.dll!System.Threading.ManualResetEventSlim.Wait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken)  Unknown
    mscorlib.dll!System.Threading.Tasks.Task.SpinThenBlockingWait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken)    Unknown
    mscorlib.dll!System.Threading.Tasks.Task.InternalWait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken)    Unknown
    mscorlib.dll!System.Threading.Tasks.Task.Wait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken)    Unknown
    mscorlib.dll!System.Threading.Tasks.Task.Wait(System.TimeSpan timeout)  Unknown
    Microsoft.VisualStudio.Threading.dll!Microsoft.VisualStudio.Threading.JoinableTaskFactory.WaitSynchronouslyCore(System.Threading.Tasks.Task task)   Unknown
    Microsoft.VisualStudio.Threading.dll!Microsoft.VisualStudio.Threading.JoinableTaskFactory.WaitSynchronously(System.Threading.Tasks.Task task)   Unknown
    Microsoft.VisualStudio.Threading.dll!Microsoft.VisualStudio.Threading.JoinableTask.CompleteOnCurrentThread()    Unknown
    Microsoft.VisualStudio.Threading.dll!Microsoft.VisualStudio.Threading.JoinableTask<Microsoft.VisualStudio.ProjectSystem.VS.Implementation.PropertyPages.DynamicType>.CompleteOnCurrentThread()  Unknown
    Microsoft.VisualStudio.Threading.dll!Microsoft.VisualStudio.Threading.JoinableTaskFactory.Run<Microsoft.VisualStudio.ProjectSystem.VS.Implementation.PropertyPages.DynamicType>(System.Func<System.Threading.Tasks.Task<Microsoft.VisualStudio.ProjectSystem.VS.Implementation.PropertyPages.DynamicType>> asyncMethod, Microsoft.VisualStudio.Threading.JoinableTaskCreationOptions creationOptions)   Unknown
    Microsoft.VisualStudio.Threading.dll!Microsoft.VisualStudio.Threading.JoinableTaskFactory.Run<Microsoft.VisualStudio.ProjectSystem.VS.Implementation.PropertyPages.DynamicType>(System.Func<System.Threading.Tasks.Task<Microsoft.VisualStudio.ProjectSystem.VS.Implementation.PropertyPages.DynamicType>> asyncMethod) Unknown
    Microsoft.VisualStudio.ProjectSystem.Implementation.dll!Microsoft.VisualStudio.ProjectSystem.ProjectMultiThreadedService.ExecuteSynchronously<Microsoft.VisualStudio.ProjectSystem.VS.Implementation.PropertyPages.DynamicType>(System.Func<System.Threading.Tasks.Task<Microsoft.VisualStudio.ProjectSystem.VS.Implementation.PropertyPages.DynamicType>> asyncAction) Unknown
    Microsoft.VisualStudio.ProjectSystem.VS.Implementation.dll!Microsoft.VisualStudio.ProjectSystem.VS.Implementation.PropertyPages.DynamicTypeBrowseObjectBase.InnerDynamicType.get()  Unknown
    Microsoft.VisualStudio.ProjectSystem.VS.Implementation.dll!Microsoft.VisualStudio.ProjectSystem.VS.Implementation.PropertyPages.DynamicTypeBrowseObjectBase.System.ComponentModel.ICustomTypeDescriptor.GetComponentName()  Unknown
    System.dll!System.ComponentModel.TypeDescriptor.MergedTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetComponentName() Unknown
    System.dll!System.ComponentModel.ReflectTypeDescriptionProvider.GetFullComponentName(object component)  Unknown
    System.dll!System.ComponentModel.TypeDescriptor.TypeDescriptionNode.GetFullComponentName(object component)  Unknown
    System.dll!System.ComponentModel.DelegatingTypeDescriptionProvider.GetFullComponentName(object component)   Unknown
    System.dll!System.ComponentModel.TypeDescriptor.TypeDescriptionNode.GetFullComponentName(object component)  Unknown
    System.dll!System.ComponentModel.TypeDescriptor.GetFullComponentName(object component)  Unknown
    Microsoft.VisualStudio.dll!Microsoft.VisualStudio.PropertyBrowser.CBEntry.Name.get()    Unknown
    Microsoft.VisualStudio.dll!Microsoft.VisualStudio.PropertyBrowser.CBEntry.ToString()    Unknown
    mscorlib.dll!System.Convert.ToString(object value, System.IFormatProvider provider) Unknown
    System.Windows.Forms.dll!System.Windows.Forms.ListControl.GetItemText(object item)  Unknown
    System.Windows.Forms.dll!System.Windows.Forms.ComboBox.NativeInsert(int index, object item) Unknown
    System.Windows.Forms.dll!System.Windows.Forms.ComboBox.ObjectCollection.AddInternal(object item)    Unknown
    System.Windows.Forms.dll!System.Windows.Forms.ComboBox.ObjectCollection.AddRangeInternal(System.Collections.IList items)    Unknown
    System.Windows.Forms.dll!System.Windows.Forms.ComboBox.ObjectCollection.AddRange(object[] items)    Unknown
    Microsoft.VisualStudio.dll!Microsoft.VisualStudio.PropertyBrowser.PropertyBrowser.UpdateComponentsCombobox(bool updateComboBox) Unknown
    Microsoft.VisualStudio.dll!Microsoft.VisualStudio.PropertyBrowser.PropertyBrowser.UpdateSelection(bool updateGrid, bool updateComboBox) Unknown
    Microsoft.VisualStudio.dll!Microsoft.VisualStudio.PropertyBrowser.PropertyBrowser.OnIdle(object sender, System.EventArgs e) Unknown

It doesn't repro if I keep the property browser closed during solution load, and the solution loads in under a minute.

However, once the solution load completes, there are a few successive UI hangs, where MSBuild is taking up most of the CPU and even spiked to 1 Gig of RAM. These are due to the Test Window issue, bug 366684

    Microsoft.VisualStudio.Threading.dll!Microsoft.VisualStudio.Threading.NoMessagePumpSyncContext.Wait(System.IntPtr[] waitHandles, bool waitAll, int millisecondsTimeout) Unknown
    mscorlib.dll!System.Threading.SynchronizationContext.InvokeWaitMethodHelper(System.Threading.SynchronizationContext syncContext, System.IntPtr[] waitHandles, bool waitAll, int millisecondsTimeout)    Unknown
    [Native to Managed Transition]  
    mscorlib.ni.dll!728aa507()  Unknown
    [Managed to Native Transition]  
    mscorlib.dll!System.Threading.Monitor.Wait(object obj, int millisecondsTimeout, bool exitContext)   Unknown
    mscorlib.dll!System.Threading.Monitor.Wait(object obj, int millisecondsTimeout) Unknown
    mscorlib.dll!System.Threading.ManualResetEventSlim.Wait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken)  Unknown
    mscorlib.dll!System.Threading.Tasks.Task.SpinThenBlockingWait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken)    Unknown
    mscorlib.dll!System.Threading.Tasks.Task.InternalWait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken)    Unknown
    mscorlib.dll!System.Threading.Tasks.Task.Wait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken)    Unknown
    mscorlib.dll!System.Threading.Tasks.Task.Wait(System.TimeSpan timeout)  Unknown
    Microsoft.VisualStudio.Threading.dll!Microsoft.VisualStudio.Threading.JoinableTaskFactory.WaitSynchronouslyCore(System.Threading.Tasks.Task task)   Unknown
    Microsoft.VisualStudio.Threading.dll!Microsoft.VisualStudio.Threading.JoinableTaskFactory.WaitSynchronously(System.Threading.Tasks.Task task)   Unknown
    Microsoft.VisualStudio.Threading.dll!Microsoft.VisualStudio.Threading.JoinableTask.CompleteOnCurrentThread()    Unknown
    Microsoft.VisualStudio.Threading.dll!Microsoft.VisualStudio.Threading.JoinableTask<Microsoft.VisualStudio.ProjectSystem.VS.HResult>.CompleteOnCurrentThread()   Unknown
    Microsoft.VisualStudio.Threading.dll!Microsoft.VisualStudio.Threading.JoinableTaskFactory.Run<Microsoft.VisualStudio.ProjectSystem.VS.HResult>(System.Func<System.Threading.Tasks.Task<Microsoft.VisualStudio.ProjectSystem.VS.HResult>> asyncMethod, Microsoft.VisualStudio.Threading.JoinableTaskCreationOptions creationOptions) Unknown
    Microsoft.VisualStudio.ProjectSystem.Implementation.dll!Microsoft.VisualStudio.ProjectSystem.ProjectMultiThreadedService.ExecuteSynchronously<Microsoft.VisualStudio.ProjectSystem.VS.HResult>(System.Func<System.Threading.Tasks.Task<Microsoft.VisualStudio.ProjectSystem.VS.HResult>> asyncAction)   Unknown
    Microsoft.VisualStudio.ProjectSystem.VS.Implementation.dll!Microsoft.VisualStudio.ProjectSystem.VS.Implementation.Package.ProjectNode.HrInvoke.AnonymousMethod__0() Unknown
    Microsoft.VisualStudio.ProjectSystem.VS.dll!Microsoft.VisualStudio.ProjectSystem.VS.HResult.Invoke(System.Func<Microsoft.VisualStudio.ProjectSystem.VS.HResult> action, System.IServiceProvider vsShellServiceProvider, Microsoft.VisualStudio.ProjectSystem.IProjectFaultHandlerService projectFaultHandlerService, Microsoft.VisualStudio.ProjectSystem.UnconfiguredProject project)  Unknown
    Microsoft.VisualStudio.ProjectSystem.VS.Implementation.dll!Microsoft.VisualStudio.ProjectSystem.VS.Implementation.Package.ProjectNode.HrInvoke(System.Func<System.Threading.Tasks.Task<Microsoft.VisualStudio.ProjectSystem.VS.HResult>> asyncAction, bool registerProjectFaultHandlerService)  Unknown
    Microsoft.VisualStudio.ProjectSystem.VS.Implementation.dll!Microsoft.VisualStudio.ProjectSystem.VS.Implementation.Package.ProjectConfig.OpenOutputGroup(string projectOutputGroupName, out Microsoft.VisualStudio.Shell.Interop.IVsOutputGroup ppIVsOutputGroupParam)   Unknown
    Microsoft.VisualStudio.TestWindow.Core.dll!Microsoft.VisualStudio.TestWindow.VSProjectExtensions.GetProjectOutputPath(Microsoft.VisualStudio.Shell.Interop.IVsProjectCfg2 projectConfig, string groupName, Microsoft.VisualStudio.TestWindow.Extensibility.ILogger logger)  Unknown
    Microsoft.VisualStudio.TestWindow.Core.dll!Microsoft.VisualStudio.TestWindow.VSProjectExtensions.GetKeyOutputForGroup(Microsoft.VisualStudio.Shell.Interop.IVsSolutionBuildManager buildManager, Microsoft.VisualStudio.Shell.Interop.IVsProject project, string groupName, Microsoft.VisualStudio.TestWindow.Extensibility.ILogger logger) Unknown
    Microsoft.VisualStudio.TestWindow.Core.dll!Microsoft.VisualStudio.TestWindow.VSProjectExtensions.GetProjectOutputPath(Microsoft.VisualStudio.Shell.Interop.IVsSolutionBuildManager buildManager, Microsoft.VisualStudio.Shell.Interop.IVsProject project, Microsoft.VisualStudio.TestWindow.Extensibility.ILogger logger)   Unknown
    Microsoft.VisualStudio.TestWindow.Core.dll!Microsoft.VisualStudio.TestWindow.VSProjectExtensions.GetProjectOutputPath(Microsoft.VisualStudio.Shell.Interop.IVsProject project, System.IServiceProvider serviceProvider, Microsoft.VisualStudio.TestWindow.Controller.SafeDispatcher safeDispatcher, Microsoft.VisualStudio.TestWindow.Extensibility.ILogger logger) Unknown
    Microsoft.VisualStudio.TestWindow.Core.dll!Microsoft.VisualStudio.TestWindow.VsAdapters.VsTestContainer.Source.get()    Unknown
    Microsoft.VisualStudio.TestWindow.Core.dll!Microsoft.VisualStudio.TestWindow.VsAdapters.VsTestContainer.CreateTimeStamp(bool deviceSelectionChanged)    Unknown
    Microsoft.VisualStudio.TestWindow.Core.dll!Microsoft.VisualStudio.TestWindow.VsAdapters.VsTestContainer.VsTestContainer(Microsoft.VisualStudio.TestWindow.Extensibility.ITestContainerDiscoverer discoverer, Microsoft.VisualStudio.TestWindow.Controller.SafeDispatcher safeDispatcher, Microsoft.VisualStudio.TestWindow.Extensibility.ILogger log, Microsoft.VisualStudio.Shell.Interop.IVsProject project, System.IServiceProvider serviceProvider, System.Collections.Generic.IEnumerable<System.Lazy<Microsoft.VisualStudio.TestWindow.VsAdapters.IVsAppContainerUtilities, Microsoft.VisualStudio.TestWindow.VsAdapters.INamedMetadata>> appContainerUtilities)  Unknown
    Microsoft.VisualStudio.TestWindow.Core.dll!Microsoft.VisualStudio.TestWindow.VsAdapters.VsProjectOutputContainerDiscoverer.get_TestContainers.AnonymousMethod__12_0(Microsoft.VisualStudio.Shell.Interop.IVsProject p)  Unknown
    System.Core.dll!System.Linq.Enumerable.WhereSelectEnumerableIterator<Microsoft.VisualStudio.Shell.Interop.IVsProject, Microsoft.VisualStudio.TestWindow.VsAdapters.VsTestContainer>.MoveNext()  Unknown
    System.Core.dll!System.Linq.Enumerable.WhereEnumerableIterator<Microsoft.VisualStudio.TestWindow.VsAdapters.VsTestContainer>.MoveNext() Unknown
    mscorlib.dll!System.Collections.Generic.List<Microsoft.VisualStudio.TestWindow.Extensibility.ITestContainer>.List(System.Collections.Generic.IEnumerable<Microsoft.VisualStudio.TestWindow.Extensibility.ITestContainer> collection)    Unknown
Microsoft.VisualStudio.Threading.JoinableTask<Microsoft.VisualStudio.ProjectSystem.VS.HResult>.CompleteOnCurrentThread()    Unknown
    Microsoft.VisualStudio.Threading.dll!Microsoft.VisualStudio.Threading.JoinableTaskFactory.Run<Microsoft.VisualStudio.ProjectSystem.VS.HResult>(System.Func<System.Threading.Tasks.Task<Microsoft.VisualStudio.ProjectSystem.VS.HResult>>

I am unable to repro any UI hang during solution build - I was able to open/edit files just fine during build. I'll keep playing with the solution a bit more.

Eilon commented 7 years ago

I just tried using Dev15 15.0.26129.0 D15REL (the build that JoC just asked everyone to install) and though it didn't quite take 15 minute to open, it was probably around 10 minutes (on my laptop), and VS was super slow for quite a while even after it opened.

NTaylorMullen commented 7 years ago

@mavasani the issue you linked accurately depicts all the perf issues the Mvc solution is running into within the Repro Steps section.

As for solution build not hanging on your end. Should I try and update my VS or download a different skew? It's pretty consistent for me.

mavasani commented 7 years ago

@NTaylorMullen @Eilon can you please share ETL traces for the hangs (my alias is mavasani)? Note that I did a clean install of the d15prerel 26130.00 and the only hangs I see were the couple mentioned above (PropertyBrowser and Test Window). I have tried closing/re-opening/build solution and opening and editing source files, and those seem to work fine.

@lifengl @srivatsn is the property browser issue known?

Eilon commented 7 years ago

Hmm, odd, when I try it again now I'm not seeing the same perf issues as before. It's still a bit slow to load, but you'd expect some slowness with this many projects. But I'm not seeing the 10-15min issue...

lifengl commented 7 years ago

I saw some hang when you load a large project with the property sheet window open couple month ago. That is largely because we show some project properties coming from design time build (like assembly version...) Not sure whether it is still the case. Making some of those properties hidden will prevent this problem. @jinujoseph, did we make the change into the product?.

lifengl commented 7 years ago

Also, connected service team fixed one performance problem last Friday, which impacts solution load time, and @BillHiebert is working a fix for an issue inside .Net Core Web project. If your solution contains any web project, it might be related.

NTaylorMullen commented 7 years ago

@lifengl Mvc contains many web projects so that could definitely be a factor.

mavasani commented 7 years ago

@NTaylorMullen @Eilon were you able to get any perf traces for the UI delays that we can investigate? Summarizing the current set of identified issues:

PropertyBrowser UI delay on open solution (intermittent): @jinujoseph is working on a fix. Jinu, do you have a tracking bug?
Connected service team issue, impacting solution load for web projects.
Test Window UI delay on open solution, and intermittently even while attempting to open/edit source files: Tracked by 366684. Note the update I made to that bug today - On the latest VS builds, I am not seeing other UI delays mentioned in its repro steps, except the ones from Test Window.

NTaylorMullen commented 7 years ago

@mavasani I haven't been able to yet. Upgraded my VS and things seem to be broken. Trying to get back to a state where I can gather that info.

NTaylorMullen commented 7 years ago

@mavasani after updating VS (d15rel) every sln I now open results in: Error occurred while restoring NuGet packages: The operation failed as details for project SomeProjectName could not be loaded. Upon unloading that project the error then moves to the next project.

I've tried workarounds mentioned here but no luck.

NTaylorMullen commented 7 years ago

Found the cause of my issue mentioned above: https://github.com/NuGet/Home/issues/4496. Working on getting ETL traces for an already restored project.

NTaylorMullen commented 7 years ago

Got a few ETL traces. Opening MVC after it already being restored took nearly 10 minutes, here's the ETL: ‪\NTaylorMullen\SHARED\ETLVS\MvcOnOpen.etl.zip

Next I tried building MVC, It's still going with progress bar not even half way so I stopped it at almost the 25 min mark, here's the ETL: ‪\NTaylorMullen\SHARED\ETLVS\MvcBuild.zip

For both of these experiments I had the following windows focused:

Test Explorer
Output
Solution Explorer

For all these tests there were significant VS not responding hangs.

I was using the optimized (less package refs, build bits etc.) nimullen/migration branch.

mavasani commented 7 years ago

@NTaylorMullen I see TestWindow and CPS design time builds on your trace, most of the time devenv is blocked on msbuild. I'll forward you instructions to patch your machine with TestWindow fix, and you can give it a try again and share new traces?

NTaylorMullen commented 7 years ago

@mavasani sounds good.

mavasani commented 7 years ago

For the build scenario, I see that almost 90% of time is spent in trying to write to the output window Microsoft.VisualStudio.ProjectSystem.VS.Implementation.VsOutputWindowTextWriterFactory+OutputWindowTextWriter+OutputStringAndCompletion.WriteToOutput:

Name                                                                                                                                                                                                                                                                                                                                                    Inc %         Inc   Exc %       Exc
kernelbase!lstrlenW                                                                                                                                                                                                                                                                                                                                     89.3      614,924   89.3    614,924
+ msenv!VsUtil::CString::Append                                                                                                                                                                                                                                                                                                                         89.3      614,906    0.0          0
|+ msenv!VsUtil::CString::Append                                                                                                                                                                                                                                                                                                                        89.3      614,786    0.0          0
||+ msenv!CSUIBuilder::WriteBufferedOutputString                                                                                                                                                                                                                                                                                                        89.3      614,786    0.0          0
|| + msenv!CSUIBuilder::FBufferedOutputString                                                                                                                                                                                                                                                                                                           89.3      614,786    0.0          0
||  + msenv!CSUIBuilder::OutputStringNoPump                                                                                                                                                                                                                                                                                                             89.3      614,786    0.0          0
||   + microsoft.visualstudio.projectsystem.vs.implementation!dynamicClass.IL_STUB_CLRtoCOM(class System.String)                                                                                                                                                                                                                                        89.3      614,786    0.0          0
||    + microsoft.visualstudio.projectsystem.vs.implementation!Utilities.OutputStringTryNoPump                                                                                                                                                                                                                                                          89.3      614,786    0.0          0
||     + microsoft.visualstudio.projectsystem.vs.implementation!Microsoft.VisualStudio.ProjectSystem.VS.Implementation.VsOutputWindowTextWriterFactory+OutputWindowTextWriter+OutputStringAndCompletion.WriteToOutput(class Microsoft.VisualStudio.Shell.Interop.IVsOutputWindowPane3,class Microsoft.VisualStudio.Shell.Interop.IVsOutputWindowPane)   89.3      614,786    0.0          0
||      + microsoft.visualstudio.projectsystem.vs.implementation!Microsoft.VisualStudio.ProjectSystem.VS.Implementation.VsOutputWindowTextWriterFactory+OutputWindowTextWriter+<>c__DisplayClass31_0+<<StartWriteOuputUnderPriority>b__0>d.MoveNext()                                                                                                   89.3      614,786    0.0          0

@lifengl @jviau Can CPS investigate this?

NTaylorMullen commented 7 years ago

@mavasani I do have diagnostics on. That could be the reason for that.

srivatsn commented 7 years ago

Ya Dave had filed https://github.com/dotnet/roslyn-project-system/issues/1242. Can you try with Diagnostics offset to minimal?

lifengl commented 7 years ago

I can take a look the trace. We saw this from perf Watson reports as well. I wonder something regressed here, because we haven't seen this for quite some time now.

Sent from my phone

On Feb 3, 2017, at 5:24 PM, Srivatsn Narayanan notifications@github.com<mailto:notifications@github.com> wrote:

Ya Dave had filed #1242https://github.com/dotnet/roslyn-project-system/issues/1242. Can you try with Diagnostics offset to minimal?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHubhttps://github.com/dotnet/roslyn-project-system/issues/1384#issuecomment-277406376, or mute the threadhttps://github.com/notifications/unsubscribe-auth/ALGWwkaGpHSK8iJfvKmmrLYu1UcCuXmrks5rY9NQgaJpZM4LyHhu.

NTaylorMullen commented 7 years ago

I've gone ahead and re-done tests without diagnostic tracing on and with the private test explorer fix from @mavasani . Opening the solution and building it worked fine this time around. There were a few issues however:

I changed the solution by checking out a different branch and that requested that I reload the solution. It looked like that hung indefinitely and I had to kill the process from task manager. ETL: ‪\NTaylorMullen\SHARED\ETLVS\Reload.etl.zip
After the Mvc build had completed it looked as if there were a lot of errors (have to find out why but they also repro at command line); VS then hung for a verry long time, had to kill the process again from task manager after around 15 minutes. ETL: ‪\NTaylorMullen\SHARED\ETLVS\AfterBuildHang.etl.zip

lifengl commented 7 years ago

Based on the trace (\NTaylorMullen\SHARED\ETLVS\AfterBuildHang.etl.zip), it looks like a problem in the test window code. Maybe a dead lock

Name Inc % Inc Exc % Exc Fold When First Last | || + microsoft.visualstudio.testwindow.core!UpdateSolutionEventsListener.UpdateSolution_Done 12.7 14,762 0.0 0 0 00000000000011000100101011110101 181.728 179,902.536 | || + microsoft.visualstudio.testwindow.core!UpdateSolutionEventsListener.OnBuildComplete 12.7 14,762 0.0 0 0 00000000000011000100101011110101 181.728 179,902.536 | || + microsoft.visualstudio.testwindow.core!VsProjectOutputContainerDiscoverer.OnBuildCompleted 12.7 14,762 0.0 0 0 00000000000011000100101011110101 181.728 179,902.536

lifengl commented 7 years ago

I looked into the build trace, and it was clearly a performance issue in the output window side.

Name Inc % Inc Exc % Exc Fold When ||+ msenv!CSUIBuilder::OutputStringNoPump 92.8 639,072 0.3 2,356 2,356 399999599989999999999999999998 || + msenv!CSUIBuilder::FBufferedOutputString 91.5 630,242 0.1 831 733 399999599989999999999999999997 || |+ msenv!CSUIBuilder::WriteBufferedOutputString 91.4 629,382 0.0 35 20 399999599989999999999999999997 || ||+ msenv!VsUtil::CString::Append 91.4 629,293 0.0 251 240 399999599989999999999999999997 || |||+ msenv!VsUtil::CString::Append 91.3 628,916 0.0 168 128 399999599989999999999999999997 || ||||+ kernelbase!lstrlenW 89.3 614,786 89.3 614,786 2,857 399999599989999999999999999997

Basically, the code breaks down the input string into lines, and append them piece by piece to an internal buffer. Every appending, it will recalculate the length of the string in the buffer, and the length of the new string, although both of them known, and then reallocate the buffer. It is repeated for every line and every call. I think it should change the code to buffer the original strings into a list, and merge them together in one call, so the buffer size can be calculated before hand to prevent all extra allocation/copy and resizing. I will loop the right team. I don't think any change on the CPS side can fix or reduce this problem.

mavasani commented 7 years ago

@NTaylorMullen Thanks for the traces. The Reload.etl.zip VS deadlock on reload/close solution is a dupe of https://github.com/dotnet/roslyn/issues/14479. I see that the UI thread is stuck on microsoft.visualstudio.languageservices.implementation!CPSProject.Disconnect, which is at the bottom of the call stack in https://github.com/dotnet/roslyn/issues/14479#issue-182660713.

This was fixed by @dpoeschl couple of days ago, so hopefully won't be part of the next build with Roslyn insertion. David, do we know what build has your deadlock fix?

mavasani commented 7 years ago

@NTaylorMullen @Eilon - let me summarize the current findings again:

Open solution works reasonsable fine now, modulo the Test Window fix for VSO 366684 - this is currently being prepped for Escrow.
Close/Reload solution deadlock: I have hit this multiple times myself and this Roslyn fix should address it.
Build with diagnostic logging: You have a workaround and the underlying issue is tracked by #1242.

Let me know if there is anything else that I have missed out and needs investigation. Otherwise, I'll keep this as a tracking bug to verify once the fixes for 1. and 2. above have been verified on an official build.

dpoeschl commented 7 years ago

@mavasani I just tested with d15rerl 26205.0 today and I couldn't repro the deadlock.

mavasani commented 7 years ago

Thanks, I'll test the MVC solution on the same build. @NTaylorMullen, please let us know if you get a deadlock on this build.

mavasani commented 7 years ago

I verified the deadlock on close solution doesn't repro for the MVC solution on 26205.0 and even Open solution is fine after applying the final Test Window private bits.

mavasani commented 7 years ago

@NTaylorMullen @Eilon - I am going to close this issue now, unless you have any further repros/traces for us to investigate.

NTaylorMullen commented 7 years ago

@mavasani Any idea when d15rel will be at a state that has all of the fixes that make using the Mvc.sln possible?

mavasani commented 7 years ago

@srivatsn Do we know when the Test Window fix is going in? We can update this issue once we have a build with the Test Window fix.

srivatsn commented 7 years ago

Likely tomorrow.

jac009 commented 7 years ago

@NTaylorMullen later this week.

NTaylorMullen commented 7 years ago

I'm testing out MVC with some of the later builds (trying to find other issues) and I'm seeing some Roslyn IntelliSense problems with the Mvc.sln now. By closing out test explorer, property browser etc. I was able to open the solution, get it to restore, and build.

I ran into this guy:

Which seemed to go away when I forced a re-restore/re-build. After re-restoring/re-building successfully I then played around with some of the source files. Opening Mvc.sln => Mvc\src\Microsoft.AspNetCore.Mvc\MvcServiceCollectionExtensions.cs shows several errors indicating that Roslyn doesn't see some package refs:

In this case it's 1 of 2 directly referenced package refs <PackageReference Include="Microsoft.Extensions.DependencyInjection" Version="1.2.0-*" />.

Tried reproducing this on other projects with no avail. Anyone able to see this on their box with the Mvc.sln (checkout the nimullen/migration branch)? My VS is: 26208.0.d15rel

mavasani commented 7 years ago

@NTaylorMullen I'll investigate this now.

mavasani commented 7 years ago

@NTaylorMullen I am seeing different behavior then yours.

After cloning the repo and opening it in VS before doing any command line operations, restore fails for me with errors of the form Error occurred while restoring NuGet packages: The operation failed as details for project RoutingWebSite could not be loaded
I closed VS and ran build.cmd from command line, which worked fine.
Repen VS, solution opens fine, and I get proper intellisense without squiggles and no design time errors or warnings.
Build from VS succeeds with same set of warnings as from command line: Unable to determine active git branch. '.git/HEAD' file in unexpected format: 'd3cce192925ff41d0d79aba3728ab1ff80962a49'

I'll try to clean my enlistment and the nuget package cache and try the steps again. I'll file an issue on NuGet if (1) repros again.

mavasani commented 7 years ago

I am unable to repro the design time warnings about SkipCompilerExecution, but can repro the squiggles when opening certain source files - investigating further now. 382039 is tracking SkipCompilerExecution issues.

Eilon commented 7 years ago

BTW @NTaylorMullen is out sick today so it might be a short while until he can provide more details.

mavasani commented 7 years ago

Update: The squiggles from opening certain source files seems to be completely indeterministic, I haven't been able to repro it since I first saw it. Even the NuGet restore failures are not reproing after cleaning the enlistment and NuGet package cache and reattempting to build.

NTaylorMullen commented 7 years ago

@mavasani lol oh goodneses. Well, hopefully the blessed release that's supposed to fix the MVC issues will "just work" once it's out 😄

Eilon commented 7 years ago

To add another data point, @sebastienros is working on a solution w/ 100 projects (using the new csproj) and was also hitting enormous slowdowns. Here's one related VSFeedback item that he filed: https://vsfeedback/comment/806237.

But beyond that issue, he's been seeing slowdowns like what's discussed in this thread.

You can try out the branch here: https://github.com/OrchardCMS/Orchard2/tree/static

mavasani commented 7 years ago

@Eilon Thanks, I'll play around with the new solution.

mavasani commented 7 years ago

@Eilon I played around with the solution for a bit and noticed the biggest UI delays are coming from the Test Window, similar to the MVC solution - these don't appear after applying the patched Test Window bits, and I was able to do most of the operations fine in the IDE (open files, edit, intellisense, restore).

However, I hit a VS deadlock in the patched Test Window binary at the end of solution build - I am going to report the dump to the Test Window folks to investigate further.

davkean commented 7 years ago

@NTaylorMullen We're tracking those build errors here: https://github.com/dotnet/roslyn-project-system/issues/1554. I'll be investigating today.

NTaylorMullen commented 7 years ago

@davkean thanks, i'll keep an eye on that.

dotnet / project-system

Solution with 56 projects is unsable once migrated to csproj. #1384