search

NuGet / Home

Repo for NuGet Client issues
Other
1.5k stars 253 forks source link

Nuget.exe actions take long to execute #8127

Closed DavidBarth closed 3 years ago

DavidBarth commented 5 years ago

Remove the content above here and fill out details below.

Details about Problem

NuGet product used: NuGet.exe NuGet version 3.4.4.1321

OS version (i.e. win10 v1607 (14393.321)):

Worked before? Yes. Having issues with perfomance.

  1. Execuring nuget actions took 2.5+ minutes when installing Cake and Nunit packages on TFS Version 15.117.27414.0

2019-05-13T12:40:40.1502988Z Executing nuget actions took 2.5 min

rrelyea commented 5 years ago

Can you tell us more about what you were doing? Update? Install? Restore? Uninstall?

What sources were you using? nuget.org?

By the way, upgrading to NuGet 4.9.4 should have several security and perf improvements.

DavidBarth commented 5 years ago

Thanks for the quick reply. We are installing packages on an on premise TFS agent in via Cake script. We use local caches to retrieve packages.

We did the nuget.exe upgrade as we speak and running a build at the moment to see the outcome.

Retrieve Add Successful install Nuget actions take long time

skofman1 commented 5 years ago

If you were interacting with nuget.org, you might have been effected by an Azure networking incident. This was already resolved. Are you still seeing slowness? image

rrelyea commented 5 years ago

@DavidBarth - can you describe the sources you have in more detail? how many. What type? is nuget.org one of them? Are any of the sources upstreaming to nuget.org?

rrelyea commented 5 years ago

Planning to close, assuming this was caused by the networking problem on nuget.org. Let us know if that is not the case.

DavidBarth commented 5 years ago

Hello, this isn't a network related issue.. we run Cake scripts on our build servers and an in process nuget.exe is dealing with Nuget operations. We have a prioritized list of Nuget caches with local caches first and we currently don't make calls to nuget.org. We updated nuget.exe and cake.exe to the latest version but haven't seen any improvement.

The below log shows 2.76 minutes of Nuget action for installing the NUnit console runner which we think is slow.

2019-05-13T12:32:39.1810869Z Retrieving package 'NUnit.ConsoleRunner 3.9.0' from 2019-05-13T12:32:39.1810869Z 2019-05-13T12:32:39.1810869Z 2019-05-13T12:32:39.2748366Z Adding package 'NUnit.ConsoleRunner.3.9.0' to folder 2019-05-13T12:32:39.2748366Z 2019-05-13T12:32:39.2748366Z 2019-05-13T12:35:24.7124957Z Added package 'NUnit.ConsoleRunner.3.9.0' to folder 2019-05-13T12:35:24.7124957Z 2019-05-13T12:35:24.7124957Z 2019-05-13T12:35:24.7124957Z Added package 'NUnit.ConsoleRunner.3.9.0' to folder 2019-05-13T12:35:24.7124957Z 2019-05-13T12:35:24.7124957Z 2019-05-13T12:35:24.7124957Z Successfully installed 'NUnit.ConsoleRunner 3.9.0' 2019-05-13T12:35:24.7124957Z 2019-05-13T12:35:24.7124957Z

2019-05-13T12:35:24.7124957Z Executing nuget actions took 2.76 min

zivkan commented 5 years ago

You have only told us the symptom, but we don't know the scenario that led to it.

If you run nuget before running your cake scripts, is the performance the same, or does the slow restore performance only happen when you run nuget as part of the cake script? I've never used cake, so I'd really appreciate if you could let us know the exact command line that cake executes, which also lets us isolate cake's influence on nuget.

are you running a series of "nuget install " or are you running "nuget restore"? If you're running restore, are you sequentially restoring individual projects, or restoring the solution and letting NuGet do work in parallel?

repeat of Rob's question: Where are your packages sourced from? Are you downloading from nuget.org, or a Azure DevOps private feed, or an on-prem private feed, myget, somewhere else? If nuget.exe is downloadig from a very slow feed

It's just a guess, but based on the log messages, it sounds like you're doing a series of "nuget install" commmands. If that's correct, you'd be far better off adding package references to your .NET projects, then letting nuget restore the solution, so that way all projects and packages are restored in parallel.

nkolev92 commented 5 years ago

Another thing. 3.4.4 is an old version :) Ideally you'd run newer versions of NuGet.exe :)

DavidBarth commented 5 years ago

Hello, thanks for the reply. Cake is running before Nuget. We have configured Nuget in our Cake.config file to use in process client. We run Nuget installs on build agents working directory We source the packages locally from the build servers file system. Nuget.exe isn not downloading packages.

We have seen an improvement on installing signed package in an offline mode running the install from command line. The issue lies in Nuget reaching out to the revocation server which is timing out.

https://docs.microsoft.com/en-us/nuget/reference/errors-and-warnings/nu3028#revocation-check-mode

We have upgraded Cake to 0.33.0 and Nuget to 4.9.2 and used the workaround suggested in the above doc. and now expecting improvement in our build time on TFS.

nkolev92 commented 4 years ago

Hey @DavidBarth

Do you recall if you observed any improvements with newer NuGet?

For your local feeds, are you using the hierarchical feeds or flat feeds? https://docs.microsoft.com/en-us/nuget/hosting-packages/local-feeds#initializing-and-maintaining-hierarchical-folders

Hierarchical feeds are significantly faster.

Given that this has been open a while without too much additional feedback, we don't think we'll be able to get to this issue, so any additional details you can provide would help us determine if there's anything actionable we can do.

hoborm commented 3 years ago

Hi @nkolev92 , I've experienced similar symptoms as mentioned in the original issue. Let me link you my comment on azure-pipelines-agent. https://github.com/microsoft/azure-pipelines-agent/issues/2356#issuecomment-703588586

The common factor in our problem was always that NuGet.exe was run from a host process which was a service. I think it should be case easy enough to replicate. (crossing out cake and TFS) If you think it's a different issue let me know and I'll open a new one.

dovholuk commented 3 years ago

I upgraded to Version 16.8.1... Executing nuget actions took 24.29 min


Attempting to gather dependency information for package 'NLog.4.7.5' with respect to project 'TestConsoleApp.NETFramework', targeting '.NETFramework,Version=v4.7.2'
Gathering dependency information took 97 ms
Attempting to resolve dependencies for package 'NLog.4.7.5' with DependencyBehavior 'Lowest'
Resolving dependency information took 0 ms
Resolving actions to install package 'NLog.4.7.5'
Resolved actions to install package 'NLog.4.7.5'
Package 'NLog.4.7.5' already exists in folder 'C:\Users\d\source\repos\TestConsoleApp\packages'
Added package 'NLog.4.7.5' to 'packages.config'
Successfully installed 'NLog 4.7.5' to TestConsoleApp.NETFramework
Executing nuget actions took 24.29 min
Time Elapsed: 00:24:32.9820485
========== Finished ==========
DavidBarth commented 3 years ago

@nkolev92 hi there, sorry for the late replies to all. Transitioned to other projects shortly after the inital question. Hope you all got the issues resolved.

DavidBarth commented 3 years ago

@dovholuk sorry didn't mean to close issue just yet, however I cannot add anything further as not working in related area anymore now. Hope you can find the above discussions useful. If not I'll close the issue as it's been while. Cheers

dovholuknf commented 3 years ago

I only commented here since this is one of the top search results I kept finding and the issue was still open. I'm not sure if this is visual studio, nuget, or some bizarre combination of the two mixed with some other craziness. I would just much prefera timeout that's reasonable to download a single artifact... Like 30s (or less maybe).

I also couldn't find any reasonable mechanism to troubleshoot the operation.

If it doesn't make sense to keep it open and you want to close it, I understand. :)

nkolev92 commented 3 years ago

@dovholuknf

Any chance you can provide us with a repro project?

Is the action that you are running a packages.config package installation?

dovholuknf commented 3 years ago

I didn't think I could. I don't know if it's reproducible tbh. I just did these steps locally and i'm now waiting on NuGET:

i can share the project but i doubt it'll be useful? I'll also post back after it's done because it's still going...

dovholuknf commented 3 years ago 
Attempting to gather dependency information for package 'NLog.4.7.5' with respect to project 'WindowsService1', targeting '.NETFramework,Version=v4.7.2'
Gathering dependency information took 8 ms
Attempting to resolve dependencies for package 'NLog.4.7.5' with DependencyBehavior 'Lowest'
Resolving dependency information took 0 ms
Resolving actions to install package 'NLog.4.7.5'
Resolved actions to install package 'NLog.4.7.5'
Adding package 'NLog.4.7.5' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'NLog.4.7.5' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'NLog.4.7.5' to 'packages.config'
Successfully installed 'NLog 4.7.5' to WindowsService1
Executing nuget actions took 6.08 min
Time Elapsed: 00:06:05.0989327
========== Finished ==========
dovholuknf commented 3 years ago

i literally can sit there and watch the dependencies pull in... here's three screen caps i grabbed while NLog was doing it's thing... see how i can spot each new dependency get added. that's how slow it is: image

dovholuknf commented 3 years ago

and - last comment till i hear back - removing a dependency can also take a lifetime... I am removing "Newtonsoft.Json" from this "WindowsService1"project right now - and it's taking foooorrrrevverrrrrr. a banner popped up saying "dowloading missing dependencies" (on a REMOVE action mind you - doesn't really make sense to try to download a missing dependency when i'm REMOVING a dependency does it?)

I know this is TOTALLY crazy but - clicking around in the VS UI either has some effect or it's a placebo... it seems to make things "go faster". frankly - that sounds insane but i do it anyway just to do something while i wait...

here's the removal time... 11.27sec --> elapsed time 59s? 


Attempting to gather dependency information for package 'Newtonsoft.Json.12.0.3' with respect to project 'WindowsService1', targeting '.NETFramework,Version=v4.7.2'
Resolving actions to uninstall package 'Newtonsoft.Json.12.0.3'
Resolved actions to uninstall package 'Newtonsoft.Json.12.0.3'
Removed package 'Newtonsoft.Json.12.0.3' from 'packages.config'
Successfully uninstalled 'Newtonsoft.Json.12.0.3' from WindowsService1
Removing package 'Newtonsoft.Json.12.0.3' from folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Removed package 'Newtonsoft.Json.12.0.3' from folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Executing nuget actions took 11.27 sec
Time Elapsed: 00:00:59.6465834
========== Finished ==========
nkolev92 commented 3 years ago

What's the target framework for the windows service in your case?

Installing newtonsoft.json & NLog in my case leads to a pretty quick installation. In the end, the pacakges.config leads only to 

<?xml version="1.0" encoding="utf-8"?>
<packages>
  <package id="Newtonsoft.Json" version="12.0.3" targetFramework="net472" />
  <package id="NLog" version="4.7.5" targetFramework="net472" />
</packages>

which is obviously not what you are seeing.

dovholuknf commented 3 years ago

I recorded an mp4 if you like too... targetting 4.7.2 at the moment. i think i had the same behavior using 4.8

ExampleNugetProject\WindowsService1>cat packages.config
<?xml version="1.0" encoding="utf-8"?>
<packages>
  <package id="Newtonsoft.Json" version="12.0.3" targetFramework="net472" />
  <package id="NLog" version="4.7.5" targetFramework="net472" />
</packages>
nkolev92 commented 3 years ago

It'd be great if you can upload that.

That's super weird :/ I see the framework assemblies too, but they are not taking as long.

The package installation in packages.config is fundamentally broken, because it involves writing every single file into the project file, and well that can be slow given the old architecture of some project-systems.

PackageReference avoids this by automatically inferring these things from a json file, but that obviously can't help you right now.

dovholuknf commented 3 years ago

recording of a 59s interaction can be found here https://www.youtube.com/watch?v=8NtNBj6bKck

it's not every time. i can't find any steps to reproduce. this shows the addition of newtonsoft.json

nkolev92 commented 3 years ago

Thanks for all that info.

The interesting part is that the download is taking a long time for you. Do you have problem accessing nuget.org? Any slowness when you just run restore or only installation?

dovholuknf commented 3 years ago

nope - never have an issue accessing nuget.org usually. personally i feel like this is something in visual studio and not so much nuget but i don't have any proof whatsoever - just a gut feeling given how the UI reacts. 300-500 ms with curl. also some of the times it's "normal fast" to pull an artifact - like 1-5 total seconds

curl -sL -w "%{http_code} %{time_starttransfer} %{url_effective}\n\\n" "http://www.nuget.org/" -o /dev/null
200 0.320062 https://www.nuget.org/
nkolev92 commented 3 years ago

Hey @dovholuk

I think collecting an ETL trace is the best thing leftover here: https://docs.microsoft.com/en-us/visualstudio/ide/report-a-problem-perfview?view=vs-2019.

dovholuknf commented 3 years ago

Tonight it happened immediately. I had also done a fresh restart just before doing this... The file is 'pretty enormous' because it collected data for 7m 45s... (how long it took for NuGet to add the dependency. Many of these dependencies below i watched in the output window. each line took like "10seconds (or waaaaay more)" to show up.

The zip file is 450mb - what should I do with this?

Attempting to gather dependency information for package 'Microsoft.Extensions.Logging.5.0.0' with respect to project 'WindowsService1', targeting '.NETFramework,Version=v4.7.2'
Gathering dependency information took 1.55 sec
Attempting to resolve dependencies for package 'Microsoft.Extensions.Logging.5.0.0' with DependencyBehavior 'Lowest'
Resolving dependency information took 0 ms
Resolving actions to install package 'Microsoft.Extensions.Logging.5.0.0'
Resolved actions to install package 'Microsoft.Extensions.Logging.5.0.0'
Removed package 'System.Runtime.CompilerServices.Unsafe.4.5.3' from 'packages.config'
Successfully uninstalled 'System.Runtime.CompilerServices.Unsafe.4.5.3' from WindowsService1
Adding package 'Microsoft.Extensions.Logging.Abstractions.5.0.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'Microsoft.Extensions.Logging.Abstractions.5.0.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'Microsoft.Extensions.Logging.Abstractions.5.0.0' to 'packages.config'
Successfully installed 'Microsoft.Extensions.Logging.Abstractions 5.0.0' to WindowsService1
Adding package 'System.Buffers.4.5.1' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'System.Buffers.4.5.1' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'System.Buffers.4.5.1' to 'packages.config'
Successfully installed 'System.Buffers 4.5.1' to WindowsService1
Adding package 'System.Numerics.Vectors.4.5.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'System.Numerics.Vectors.4.5.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'System.Numerics.Vectors.4.5.0' to 'packages.config'
Successfully installed 'System.Numerics.Vectors 4.5.0' to WindowsService1
Adding package 'System.Runtime.CompilerServices.Unsafe.5.0.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'System.Runtime.CompilerServices.Unsafe.5.0.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'System.Runtime.CompilerServices.Unsafe.5.0.0' to 'packages.config'
Successfully installed 'System.Runtime.CompilerServices.Unsafe 5.0.0' to WindowsService1
Adding package 'System.Memory.4.5.4' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'System.Memory.4.5.4' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'System.Memory.4.5.4' to 'packages.config'
Successfully installed 'System.Memory 4.5.4' to WindowsService1
Adding package 'Microsoft.Extensions.Primitives.5.0.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'Microsoft.Extensions.Primitives.5.0.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'Microsoft.Extensions.Primitives.5.0.0' to 'packages.config'
Successfully installed 'Microsoft.Extensions.Primitives 5.0.0' to WindowsService1
Adding package 'Microsoft.Extensions.Options.5.0.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'Microsoft.Extensions.Options.5.0.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'Microsoft.Extensions.Options.5.0.0' to 'packages.config'
Successfully installed 'Microsoft.Extensions.Options 5.0.0' to WindowsService1
Adding package 'System.Diagnostics.DiagnosticSource.5.0.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'System.Diagnostics.DiagnosticSource.5.0.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'System.Diagnostics.DiagnosticSource.5.0.0' to 'packages.config'
Successfully installed 'System.Diagnostics.DiagnosticSource 5.0.0' to WindowsService1
Adding package 'System.ValueTuple.4.5.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'System.ValueTuple.4.5.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'System.ValueTuple.4.5.0' to 'packages.config'
Successfully installed 'System.ValueTuple 4.5.0' to WindowsService1
Adding package 'Microsoft.Extensions.Logging.5.0.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'Microsoft.Extensions.Logging.5.0.0' to folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Added package 'Microsoft.Extensions.Logging.5.0.0' to 'packages.config'
Successfully installed 'Microsoft.Extensions.Logging 5.0.0' to WindowsService1
Removing package 'System.Runtime.CompilerServices.Unsafe.4.5.3' from folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Removed package 'System.Runtime.CompilerServices.Unsafe.4.5.3' from folder 'C:\Users\cd\source\repos\ExampleNugetProject\packages'
Executing nuget actions took 5.75 min
Time Elapsed: 00:07:47.8059436
========== Finished ==========

i wish a timestamp was on each line - that might have been helpful...

dovholuknf commented 3 years ago

I tried to upload the etl over at https://developercommunity2.visualstudio.com/t/Executing-nuget-actions-took-1236-min/1259021?entry=myactivity but I don't know if it was successful.

nkolev92 commented 3 years ago

It was successful I can see it.

nkolev92 commented 3 years ago

Hey @dovholuk Given that this issue was originally about nuget.exe, I'm gonna close it and keep the issue you filled as the master one. We'll prioritize there.

StrictLine commented 2 years ago

Hello, this isn't a network related issue.. we run Cake scripts on our build servers and an in process nuget.exe is dealing with Nuget operations. We have a prioritized list of Nuget caches with local caches first and we currently don't make calls to nuget.org. We updated nuget.exe and cake.exe to the latest version but haven't seen any improvement.

The below log shows 2.76 minutes of Nuget action for installing the NUnit console runner which we think is slow.

2019-05-13T12:32:39.1810869Z Retrieving package 'NUnit.ConsoleRunner 3.9.0' from 2019-05-13T12:32:39.1810869Z 2019-05-13T12:32:39.1810869Z 2019-05-13T12:32:39.2748366Z Adding package 'NUnit.ConsoleRunner.3.9.0' to folder 2019-05-13T12:32:39.2748366Z 2019-05-13T12:32:39.2748366Z 2019-05-13T12:35:24.7124957Z Added package 'NUnit.ConsoleRunner.3.9.0' to folder 2019-05-13T12:35:24.7124957Z 2019-05-13T12:35:24.7124957Z 2019-05-13T12:35:24.7124957Z Added package 'NUnit.ConsoleRunner.3.9.0' to folder 2019-05-13T12:35:24.7124957Z 2019-05-13T12:35:24.7124957Z 2019-05-13T12:35:24.7124957Z Successfully installed 'NUnit.ConsoleRunner 3.9.0' 2019-05-13T12:35:24.7124957Z 2019-05-13T12:35:24.7124957Z

2019-05-13T12:35:24.7124957Z Executing nuget actions took 2.76 min

Hi David, I'd had the same situation with Nuget CLI and solved it by the help of this Stackoverflow answer

Signature verification seems to be a challenge on offline build servers.

Cheers, Miki