NuGet Restore + VS performance / scalability on solutions with warnings (was: corfxlab repro has some issues with Solution Open and Restore)

[rrelyea]

see internal bug 384909.
There was a recent change in the repo to move to netcorapp 1.1 from 1.0 -- and it made it better.
Other fixes in 26214.xx may have also made it better.

Let's try to repro to understand how bad it was and ensure we understand what still happens.

[pakrym]

Related: dotnet/sdk#870 ?

[zhili1208]

I can't repro it with rc4, will try 26214 later. Restore took some time due to a lots of packages, but didn't fail or crash.

[rrelyea]

Please see related email thread. Please also test with the 1.0->1.1 change reverted.

[zhili1208]

Tested on rc4 and 26214, also with the 1.0->1.1 change reverted.

Restore took around 8 mins for 62 projects and 211 packages.
During restoring, UI didn't hang, can edit code but intellisense doesn't work and got errors from intellisense due to package is not restored.
If I open some .cs file from one project, UI will hang for seconds after that project is restored, I guess that's because intellisense is updating. Then everything works well.

Hit this #4307 a lot

[zhili1208]

Perf Data:

When delete cache:
Nuget.exe restore : 2 min
Auto restore: 8 min
Solution restore: 4 min

when don't delete cache:
Nuget.exe restore: 15 second
Auto restore: 3 min
Solution restore : 2 min 44 second

[zhili1208]

I just found the repo with 1.0->1.1 change reverted(8 min) is much slower than the repo without the revert(4 min).
the number of packages is almost the same

But auto restore for the repo with 1.0->1.1 has lots of "package downgrade warning message", I think too much logging might slow down the restore

[emgarten]

Writing warnings to the error list and logging appears to be taking a lot of time here.

I used right click Restore to test instead of auto restore. This was also with reverting the 1.0->1.1 change.

With logging:
Time Elapsed: 00:02:00.0844487

With logging removed:
Time Elapsed: 00:00:11.5743181

[davkean]

Hmm, logging the Output window regressed: dotnet/project-system#1242, but it didn't look like you were logging a lot and VS didn't lock up.

[emgarten]

@davkean writing out warnings to the error list seems to be the main slow down that I have seen so far.

[davkean]

Another reason to let us do it. :)

[rrelyea]

We compared NuGet.exe vs AutoRestore vs Solution Restore.

First Major Issue: Logging Which Requires UI Thread
Looks like logging to status bar, likely logging to output window, and logging warnings requires synchronous access to the UI thread.
When corfxlab is 1.0, it gets about 6,000 downgrade warnings.
So that is why moving to 1.1 helps so much.

Second Major Issue: Auto Restore Retry
We also found that Auto-Restore perf is substantially worse as well, we believe this is related to:

#4307 CPS out of sync with Restore with larger solutions that haven't turned on LSL (lightweight solution restore, formerly called DPL)

Third Major Issue: SolutionRestore UI Unresponsiveness
Beyond this, SolutionRestore appears to cause VS to go not responding for this project:

#4636 Solution Restore of corfxlab repo causes VS to go to Not Responding

We’re attacking the Logging issue first. And then we’ll see perf/ux in the different scenarios…

[emgarten]

Fixed in 4.4.0 through several performance improvements.