Removing package from packages.config-based project is incredibly slow

[bording]

I've noticed that uninstalling a package from a project that is using packages.config seems to take an excessively long amount of time. Earlier today it took over 40 minutes, and when trying it again to write up this issue, it took almost 25 minutes, as you can see from the output below.

The package in question, NServiceBus.AcceptanceTests.Sources, includes source files via a content folder. Removing all of the content files seems to be related to what is causing it to take so long.

While waiting for it to uninstall, I noticed that the IntelliSense output window was showing a "[Failure] Could not find file ''." entry for each file in the package. It seems that the [Failure] entries were slowly showing up each time a file was removed from the project and disk.

NOTE: When using package references to reference the package, everything is fast, taking less than a second to install/uninstall.

Details about Problem

NuGet product used: VS UI VS version: VS 2017 15.7.1 OS version: win10 1803

Detailed repro steps

1. Create a new project using the Console App (.NET Framework) template
2. Install the NServiceBus.AcceptanceTests.Sources package (version 7.0.0-rc0002), choosing packages.config
3. Uninstall the package
4. Wait

Output from Package Manager window

Attempting to gather dependency information for package 'NServiceBus.AcceptanceTests.Sources.7.0.0-rc0002' with respect to project 'PackageTest', targeting '.NETFramework,Version=v4.7.2'
Resolving actions to uninstall package 'NServiceBus.AcceptanceTests.Sources.7.0.0-rc0002'
Resolved actions to uninstall package 'NServiceBus.AcceptanceTests.Sources.7.0.0-rc0002'
Removed package 'NServiceBus.AcceptanceTests.Sources.7.0.0-rc0002' from 'packages.config'
Successfully uninstalled 'NServiceBus.AcceptanceTests.Sources.7.0.0-rc0002' from PackageTest
Removing package 'NServiceBus.AcceptanceTests.Sources.7.0.0-rc0002' from folder 'c:\code\PackageTest\packages'
Removed package 'NServiceBus.AcceptanceTests.Sources.7.0.0-rc0002' from folder 'c:\code\PackageTest\packages'
Executing nuget actions took 24.33 min
Time Elapsed: 00:24:20.5775799
========== Finished ==========

[nkolev92]

I don't see as horrible of performance as in these logs.

This is what I get

Attempting to gather dependency information for package 'NServiceBus.AcceptanceTests.Sources.7.0.1' with respect to project 'ConsoleApp37', targeting '.NETFramework,Version=v4.6.2'
Resolving actions to uninstall package 'NServiceBus.AcceptanceTests.Sources.7.0.1'
Resolved actions to uninstall package 'NServiceBus.AcceptanceTests.Sources.7.0.1'
Removed package 'NServiceBus.AcceptanceTests.Sources.7.0.1' from 'packages.config'
Successfully uninstalled 'NServiceBus.AcceptanceTests.Sources.7.0.1' from ConsoleApp37
Removing package 'NServiceBus.AcceptanceTests.Sources.7.0.1' from folder 'C:\Users\nikolev.REDMOND\Source\Repos\ConsoleApp37\packages'
Removed package 'NServiceBus.AcceptanceTests.Sources.7.0.1' from folder 'C:\Users\nikolev.REDMOND\Source\Repos\ConsoleApp37\packages'
Executing nuget actions took 24.88 sec
Time Elapsed: 00:00:25.0107697
========== Finished ==========

This package has a lot of content files and currently there's no batching on project-system side to handle these cases.

We'd need an extra API from PS side to handle this.

I think the relevant code is here

/cc @jainaashish @tmeschter @rrelyea

[bording]

@nkolev92 I just tried it again:

Attempting to gather dependency information for package 'NServiceBus.AcceptanceTests.Sources.7.0.1' with respect to project 'ConsoleApp115', targeting '.NETFramework,Version=v4.6.1'
Resolving actions to uninstall package 'NServiceBus.AcceptanceTests.Sources.7.0.1'
Resolved actions to uninstall package 'NServiceBus.AcceptanceTests.Sources.7.0.1'
Removed package 'NServiceBus.AcceptanceTests.Sources.7.0.1' from 'packages.config'
Successfully uninstalled 'NServiceBus.AcceptanceTests.Sources.7.0.1' from ConsoleApp115
Removing package 'NServiceBus.AcceptanceTests.Sources.7.0.1' from folder 'C:\Users\Brandon\Documents\Visual Studio 2017\Projects\ConsoleApp115\packages'
Removed package 'NServiceBus.AcceptanceTests.Sources.7.0.1' from folder 'C:\Users\Brandon\Documents\Visual Studio 2017\Projects\ConsoleApp115\packages'
Executing nuget actions took 11.38 min
Time Elapsed: 00:11:23.1213053
========== Finished ==========

The performance is still quite bad. Can you think of anything environmental that would be making it so much quicker for you than I'm seeing?

[nkolev92]

Not really. This shouldn't be as disk intensive, and I'd imagine you'd need a really slow machine to get VS to slowdown completely.

If you can provide an etl trace for this, that would be great.

[bording]

Not really. This shouldn't be as disk intensive, and I'd imagine you'd need a really slow machine to get VS to slowdown completely.

This is a pretty high-end machine, including a Samsung 950 PRO SSD, so I don't think that's the problem!

If you can provide an etl trace for this, that would be great.

Sure, I'd be happy to. Do you have some instructions I can follow to get you what you need?

[nkolev92]

Sure.

1. Download and extract PerfView.exe. http://www.microsoft.com/en-us/download/details.aspx?id=28567
2. Run PerfView.exe collect /zip:true /nogui /threadtime:true /AcceptEULA from an elevated command prompt. This will launch another window and begin tracing.
3. Run the uninstall.
4. Press S on the window that showed up in step 2. This will generate a file called PerfViewData.ETL.ZIP.

[bording]

So of course as soon as I go to collect a trace, it starts behaving, taking about 40 seconds to uninstall!

I'll have to try it again later to find it actually acting like it has been. Once I get a trace, is okay if I email it to you instead of attaching it to the issue?

[nkolev92]

@bording

Yep, that works. nikolev[at]microsoft.com is the address.

Even 40s is pretty bad of course. We'd need to triage and prioritize respectively, because improving this would be a multi-team effort.

[bording]

@nkolev92 I was able to get the problem to repro again, and I've emailed you with information on how to get the trace.

[bording]

@nkolev92 Were you ever able to take a look at the trace?

[nkolev92]

@bording Yes I have. Unfortunately I don't have a timeline to give you right now.

[bording]

@bording Yes I have. Unfortunately I don't have a timeline to give you right now.

Did the trace actually highlight what the problem is? While having a timeline for when a fix might be made would be nice, at this point I'm more curious about the cause.

[nkolev92]

The cause was the suspected one. We're trying to process too many content files. It's hard to diagnose what's causing the variance between the different runs, so can't give you more details there without further investigation.

[nkolev92]

New report https://devdiv.visualstudio.com/DevDiv/_workitems/edit/567750.