josh-cooley commented 1 month ago

Checklist

[X] I confirm there are no unresolved issues reported on the Chocolatey Status page.
[X] I have verified this is the correct repository for opening this issue.
[X] I have verified no other issues exist related to my problem.
[ ] I have verified this is not an issue for a specific package.
[X] I have verified this issue is not security related.
[X] I confirm I am using official, and not unofficial, or modified, Chocolatey products.

What You Are Seeing?

choco upgrade my-package command takes a very long time resolving dependencies. The verbose output shows that package resolution is occurring repeatedly for the same packages. Debugging the issue shows it processing multiple versions of the same dependency in NugetCommon.GetPackageDependencies and NugetCommon.HandleDependencies

Example dependencies

graph TD;
    A-->B;
    A-->C;
    B-->D;
    C-->D;

The dependency for B->C is similar to [1.0.1000, 2.0.0) The dependency for C->D is similar to [1.0.0, 2.0.0) All versions between 1.0.0 and 1.0.1000 are resolved and dependencies for D are then resolved for each instance.

Downgrading to 1.4 allows this to work.

What is Expected?

Expect resolution to the narrowest constrained dependencies. If 1.0.1000 or newer is required, no version less than 1.0.1000 should be considered.

How Did You Get This To Happen?

I ran choco upgrade my-package -y
Waited 30 min.
Upgrade did not complete, download did not begin.

System Details

Operating System: Windows 10
Windows PowerShell version: 7.4.2
Chocolatey CLI Version: 2.2
Chocolatey Licensed Extension version: N/A
Chocolatey License type: Open Source
Terminal/Emulator: Windows Terminal

Installed Packages

7zip 21.7
7zip.install 21.7
azure-cli 2.53.0.20231015
cadinstall.extension 1.0.1
chocolatey 1.4.0
chocolatey-compatibility.extension 1.0.0
chocolatey-core.extension 1.4.0
chocolatey-dotnetfx.extension 1.0.1
chocolatey-windowsupdate.extension 1.0.4
dotnet-6.0-aspnetruntime 6.0.28
dotnet-6.0-runtime 6.0.28
dotnet-8.0-aspnetruntime 8.0.0
dotnet-8.0-runtime 8.0.0
DotNet4.6.1 4.6.01055.20170308
dotnet4.8 4.8.3761.0
erlang 25.1.2
filezilla 3.58.0
git 2.41.0
git.install 2.41.0
handle 5.0
ilspy 7.2.1
KB2919355 1.0.20160915
KB2919442 1.0.20160915
KB2999226 1.0.20181019
KB3033929 1.0.5
KB3035131 1.0.3
netfx-4.7.2 4.7.2.0
notepadplusplus 8.4.8
notepadplusplus.install 8.4.8
nuget.commandline 6.8.0
pandoc 3.1.6.2
perfview 3.1.7
procexp 17.2
procmon 3.83
rabbitmq 3.12.2
sql-server-2019 15.0.2000.20210324
sql-server-management-studio 15.0.18386.0
sqlsysclrtypes 11.2.5058.3
Tracker 10.2409.0.137
vcredist140 14.38.33130
windirstat 1.1.2.20161210
winmerge 2.16.24

Output Log

2024-05-23 16:16:25,736 61996 [INFO ] - Chocolatey v2.2.2
2024-05-23 16:16:25,741 61996 [DEBUG] - Chocolatey is running on Windows v 10.0.19045.0
2024-05-23 16:16:25,743 61996 [DEBUG] - Attempting to delete file "C:/ProgramData/chocolatey/choco.exe.old".
2024-05-23 16:16:25,743 61996 [DEBUG] - Attempting to delete file "C:\ProgramData\chocolatey\choco.exe.old".
2024-05-23 16:16:25,748 61996 [DEBUG] - Command line: "C:\ProgramData\chocolatey\choco.exe" upgrade product.db-tool -y
2024-05-23 16:16:25,749 61996 [DEBUG] - Received arguments: upgrade product.db-tool -y
2024-05-23 16:16:25,774 61996 [DEBUG] - RemovePendingPackagesTask is now ready and waiting for PreRunMessage.
2024-05-23 16:16:25,779 61996 [DEBUG] - Sending message 'PreRunMessage' out if there are subscribers...
2024-05-23 16:16:25,784 61996 [DEBUG] - [Pending] Removing all pending packages that should not be considered installed...
2024-05-23 16:16:25,814 61996 [DEBUG] - Performing validation checks.
2024-05-23 16:16:25,816 61996 [DEBUG] - Global Configuration Validation Checks:
2024-05-23 16:16:25,817 61996 [DEBUG] -  - Package Exit Code / Exit On Reboot = Checked
2024-05-23 16:16:25,819 61996 [DEBUG] - System State Validation Checks:
2024-05-23 16:16:25,821 61996 [DEBUG] -  Reboot Requirement Checks:
2024-05-23 16:16:25,822 61996 [DEBUG] -  - Pending Computer Rename = Checked
2024-05-23 16:16:25,823 61996 [DEBUG] -  - Pending Component Based Servicing = Flagged
2024-05-23 16:16:25,825 61996 [DEBUG] - Cache Folder Lockdown Checks:
2024-05-23 16:16:25,825 61996 [DEBUG] -  - Elevated State = Checked
2024-05-23 16:16:25,826 61996 [DEBUG] -  - Folder Exists = Checked
2024-05-23 16:16:25,828 61996 [DEBUG] -  - Folder lockdown = Checked
2024-05-23 16:16:25,830 61996 [INFO ] - 3 validations performed. 2 success(es), 1 warning(s), and 0 error(s).
2024-05-23 16:16:25,831 61996 [INFO ] - 
2024-05-23 16:16:25,832 61996 [WARN ] - Validation Warnings:
2024-05-23 16:16:25,833 61996 [WARN ] -  - A pending system reboot request has been detected, however, this is
   being ignored due to the current Chocolatey configuration.  If you
   want to halt when this occurs, then either set the global feature
   using:
     choco feature enable --name="exitOnRebootDetected"
   or pass the option --exit-when-reboot-detected.

2024-05-23 16:16:25,840 61996 [DEBUG] - The source 'https://chocolatey.org/api/v2/;https://pkgs.dev.azure.com/product-company/_packaging/CadChocolateyPackages/nuget/v2/' evaluated to a 'normal' source type
2024-05-23 16:16:25,841 61996 [DEBUG] - 
NOTE: Hiding sensitive configuration data! Please double and triple
 check to be sure no sensitive data is shown, especially if copying
 output to a gist for review.
2024-05-23 16:16:25,846 61996 [DEBUG] - Configuration: CommandName='upgrade'|
CacheLocation='C:\Users\myname\AppData\Local\Temp\chocolatey'|
CommandExecutionTimeoutSeconds='2700'|WebRequestTimeoutSeconds='30'|
Sources='https://chocolatey.org/api/v2/;https://pkgs.dev.azure.com/product-company/_packaging/CadChocolateyPackages/nuget/v2/'|

SourceType='normal'|ShowOnlineHelp='False'|Debug='False'|
Verbose='False'|Trace='False'|Force='False'|Noop='False'|
HelpRequested='False'|UnsuccessfulParsing='False'|RegularOutput='True'|
QuietOutput='False'|PromptForConfirmation='False'|
DisableCompatibilityChecks='False'|AcceptLicense='True'|
AllowUnofficialBuild='False'|Input='MaintainCadDb'|AllVersions='False'|
SkipPackageInstallProvider='False'|SkipHookScripts='False'|
PackageNames='MaintainCadDb'|Prerelease='False'|ForceX86='False'|
OverrideArguments='False'|NotSilent='False'|
ApplyPackageParametersToDependencies='False'|
ApplyInstallArgumentsToDependencies='False'|IgnoreDependencies='False'|
CacheExpirationInMinutes='30'|AllowDowngrade='False'|
ForceDependencies='False'|PinPackage='False'|
Information.PlatformType='Windows'|
Information.PlatformVersion='10.0.19045.0'|
Information.PlatformName='Windows 10'|
Information.ChocolateyVersion='2.2.2.0'|
Information.ChocolateyProductVersion='2.2.2'|
Information.FullName='choco, Version=2.2.2.0, Culture=neutral, PublicKeyToken=79d02ea9cad655eb'|

Information.Is64BitOperatingSystem='True'|
Information.Is64BitProcess='True'|Information.IsInteractive='True'|
Information.UserName='myname'|Information.UserDomainName='INGRNET'|
Information.IsUserAdministrator='True'|
Information.IsUserSystemAccount='False'|
Information.IsUserRemoteDesktop='False'|
Information.IsUserRemote='False'|Information.IsProcessElevated='True'|
Information.IsLicensedVersion='False'|
Information.IsLicensedAssemblyLoaded='False'|
Information.LicenseType='Foss'|
Information.CurrentDirectory='C:\Users\myname'|
Features.AutoUninstaller='True'|Features.ChecksumFiles='True'|
Features.AllowEmptyChecksums='False'|
Features.AllowEmptyChecksumsSecure='True'|
Features.FailOnAutoUninstaller='False'|
Features.FailOnStandardError='False'|Features.UsePowerShellHost='True'|
Features.LogEnvironmentValues='False'|Features.LogWithoutColor='False'|
Features.VirusCheck='False'|
Features.FailOnInvalidOrMissingLicense='False'|
Features.IgnoreInvalidOptionsSwitches='True'|
Features.UsePackageExitCodes='True'|
Features.UseEnhancedExitCodes='False'|
Features.UseFipsCompliantChecksums='False'|
Features.ShowNonElevatedWarnings='True'|
Features.ShowDownloadProgress='True'|
Features.StopOnFirstPackageFailure='False'|
Features.UseRememberedArgumentsForUpgrades='False'|
Features.IgnoreUnfoundPackagesOnUpgradeOutdated='False'|
Features.SkipPackageUpgradesWhenNotInstalled='False'|
Features.RemovePackageInformationOnUninstall='False'|
Features.ExitOnRebootDetected='False'|
Features.LogValidationResultsOnWarnings='True'|
Features.UsePackageRepositoryOptimizations='True'|
ListCommand.LocalOnly='False'|ListCommand.IdOnly='False'|
ListCommand.IncludeRegistryPrograms='False'|ListCommand.PageSize='25'|
ListCommand.Exact='False'|ListCommand.ByIdOnly='False'|
ListCommand.ByTagOnly='False'|ListCommand.IdStartsWith='False'|
ListCommand.OrderByPopularity='False'|ListCommand.ApprovedOnly='False'|
ListCommand.DownloadCacheAvailable='False'|
ListCommand.NotBroken='False'|
ListCommand.IncludeVersionOverrides='False'|
ListCommand.ExplicitPageSize='False'|
ListCommand.ExplicitSource='False'|
UpgradeCommand.FailOnUnfound='False'|
UpgradeCommand.FailOnNotInstalled='False'|
UpgradeCommand.NotifyOnlyAvailableUpgrades='False'|
UpgradeCommand.ExcludePrerelease='False'|
NewCommand.AutomaticPackage='False'|
NewCommand.UseOriginalTemplate='False'|SourceCommand.Command='unknown'|
SourceCommand.Priority='0'|SourceCommand.BypassProxy='False'|
SourceCommand.AllowSelfService='False'|
SourceCommand.VisibleToAdminsOnly='False'|
FeatureCommand.Command='unknown'|ConfigCommand.Command='Unknown'|
ApiKeyCommand.Command='Unknown'|PinCommand.Command='Unknown'|
OutdatedCommand.IgnorePinned='False'|
ExportCommand.IncludeVersionNumbers='False'|Proxy.BypassOnLocal='True'|
TemplateCommand.Command='unknown'|CacheCommand.Command='Unknown'|
CacheCommand.RemoveExpiredItemsOnly='False'|
2024-05-23 16:16:25,847 61996 [DEBUG] - _ Chocolatey:ChocolateyUpgradeCommand - Normal Run Mode _

followed by many pages of this

2024-05-23 16:17:03,781 61996 [INFO ] - [NuGet]   CACHE https://community.chocolatey.org/api/v2/FindPackagesById()?id='product.localization'&semVerLevel=2.0.0
2024-05-23 16:17:03,782 61996 [INFO ] - [NuGet]   CACHE https://pkgs.dev.azure.com/product-company/_packaging/CadChocolateyPackages/nuget/v2/FindPackagesById()?id='product.localization'&semVerLevel=2.0.0
2024-05-23 16:17:04,070 61996 [INFO ] - [NuGet]   CACHE https://community.chocolatey.org/api/v2/FindPackagesById()?id='product.config'&semVerLevel=2.0.0
2024-05-23 16:17:04,072 61996 [INFO ] - [NuGet]   CACHE https://pkgs.dev.azure.com/product-company/_packaging/CadChocolateyPackages/nuget/v2/FindPackagesById()?id='product.config'&semVerLevel=2.0.0
2024-05-23 16:17:04,224 61996 [INFO ] - [NuGet]   CACHE https://community.chocolatey.org/api/v2/FindPackagesById()?id='product.upgrade-tool'&semVerLevel=2.0.0
2024-05-23 16:17:04,225 61996 [INFO ] - [NuGet]   CACHE https://pkgs.dev.azure.com/product-company/_packaging/CadChocolateyPackages/nuget/v2/FindPackagesById()?id='product.upgrade-tool'&semVerLevel=2.0.0
2024-05-23 16:17:04,529 61996 [INFO ] - [NuGet]   CACHE https://community.chocolatey.org/api/v2/FindPackagesById()?id='product.localization'&semVerLevel=2.0.0
2024-05-23 16:17:04,530 61996 [INFO ] - [NuGet]   CACHE https://pkgs.dev.azure.com/product-company/_packaging/CadChocolateyPackages/nuget/v2/FindPackagesById()?id='product.localization'&semVerLevel=2.0.0
2024-05-23 16:17:04,852 61996 [INFO ] - [NuGet]   CACHE https://community.chocolatey.org/api/v2/FindPackagesById()?id='product.config'&semVerLevel=2.0.0
2024-05-23 16:17:04,854 61996 [INFO ] - [NuGet]   CACHE https://pkgs.dev.azure.com/product-company/_packaging/CadChocolateyPackages/nuget/v2/FindPackagesById()?id='product.config'&semVerLevel=2.0.0
2024-05-23 16:17:05,012 61996 [INFO ] - [NuGet]   CACHE https://community.chocolatey.org/api/v2/FindPackagesById()?id='product.localization'&semVerLevel=2.0.0
2024-05-23 16:17:05,013 61996 [INFO ] - [NuGet]   CACHE https://pkgs.dev.azure.com/product-company/_packaging/CadChocolateyPackages/nuget/v2/FindPackagesById()?id='product.localization'&semVerLevel=2.0.0
2024-05-23 16:17:05,294 61996 [INFO ] - [NuGet]   CACHE https://community.chocolatey.org/api/v2/FindPackagesById()?id='product.config'&semVerLevel=2.0.0
2024-05-23 16:17:05,295 61996 [INFO ] - [NuGet]   CACHE https://pkgs.dev.azure.com/product-company/_packaging/CadChocolateyPackages/nuget/v2/FindPackagesById()?id='product.config'&semVerLevel=2.0.0
2024-05-23 16:17:05,422 61996 [INFO ] - [NuGet]   CACHE https://community.chocolatey.org/api/v2/FindPackagesById()?id='product.upgrade-tool'&semVerLevel=2.0.0
2024-05-23 16:17:05,424 61996 [INFO ] - [NuGet]   CACHE https://pkgs.dev.azure.com/product-company/_packaging/CadChocolateyPackages/nuget/v2/FindPackagesById()?id='product.upgrade-tool'&semVerLevel=2.0.0
2024-05-23 16:17:05,752 61996 [INFO ] - [NuGet]   CACHE https://community.chocolatey.org/api/v2/FindPackagesById()?id='product.localization'&semVerLevel=2.0.0
2024-05-23 16:17:05,754 61996 [INFO ] - [NuGet]   CACHE https://pkgs.dev.azure.com/product-company/_packaging/CadChocolateyPackages/nuget/v2/FindPackagesById()?id='product.localization'&semVerLevel=2.0.0
2024-05-23 16:17:06,055 61996 [INFO ] - [NuGet]   CACHE https://community.chocolatey.org/api/v2/FindPackagesById()?id='product.config'&semVerLevel=2.0.0
2024-05-23 16:17:06,056 61996 [INFO ] - [NuGet]   CACHE https://pkgs.dev.azure.com/product-company/_packaging/CadChocolateyPackages/nuget/v2/FindPackagesById()?id='product.config'&semVerLevel=2.0.0
2024-05-23 16:17:06,232 61996 [INFO ] - [NuGet]   CACHE https://community.chocolatey.org/api/v2/FindPackagesById()?id='product.upgrade-tool'&semVerLevel=2.0.0
2024-05-23 16:17:06,234 61996 [INFO ] - [NuGet]   CACHE https://pkgs.dev.azure.com/product-company/_packaging/CadChocolateyPackages/nuget/v2/FindPackagesById()?id='product.upgrade-tool'&semVerLevel=2.0.0
2024-05-23 16:17:06,564 61996 [INFO ] - [NuGet]   CACHE https://community.chocolatey.org/api/v2/FindPackagesById()?id='product.localization'&semVerLevel=2.0.0
2024-05-23 16:17:06,565 61996 [INFO ] - [NuGet]   CACHE https://pkgs.dev.azure.com/product-company/_packaging/CadChocolateyPackages/nuget/v2/FindPackagesById()?

Additional Context

NugetCommon.HandleDependencies has a dependencyCache parameter. The cache is checked for exact matches with dependencyCache.Contains(dependency). Changing this to check the VersionRange with IsSubSetOrEqualTo allowed the upgrade to complete and target the narrowest range in the dependencies. The check looks like: dependencyCache.Any(d => d.Id == dependency.Id && d.VersionRange.IsSubSetOrEqualTo(dependency.VersionRange)); Instead of the Contains call.

pauby commented 1 month ago

I installed all of the packages and the package versions, listed above, except:

dotnet4.8 version 4.8.3761.0 (version does not exist on the Chocolatey Community Repository
cadinstall.extension (doesn't exist on the Chocolatey Community Repository).
sqlsysclrtypes (doesn't exist on the Chocolatey Community Repository).
Tracker (doesn't exist on the Chocolatey Community Repository).

You didn't supply my-package so I just did a choco upgrade all -y --no-progress:

Note to upgrade 23 packages, it took 17 minutes.

So I cannot reproduce this and suspect the issue may lie with the packages I do not have. Without my-package, the other packages, and trace logs (running the command with the --trace option) we cannot do more.

josh-cooley commented 1 month ago

Thanks for your response. This does require access to a non-public repo with all the package versions. I've been reviewing the tests to see if I can create a test that reproduces the issue. Would you be interested in a PR that includes a unit test?

pauby commented 1 month ago

We need a way to reproduce it here. The steps you provided don't allow me to do that. So everything you are doing and using is what is needed.

If you want to supply the packages in private, I'm happy to set something up.

A PR with a unit test isn't going to get us that, unfortunately.

josh-cooley commented 1 month ago

I can't provide access to the private repo or the packages we have. I will make packages that reproduce the issue that I can share.

josh-cooley commented 1 month ago

It turns out the dependency tree needs a kite tail to reproduce the graph below. I've attached a script and package files that generate the packages needed to reproduce this. I can send the packages I generated, but it's 3 MB so I did not attach it here.

In the demo-projects folder, run GeneratePackages.ps1. This will generate a single package for package-a, package-b, and package-c. It will generate 1000 packages each for package-d and package-e.

This shows up when running the upgrade even when no package is installed. I would guess it shows up when running install, but I haven't tested that yet. Here's the command I ran.

choco upgrade package-a --verbose --yes --source C:\demo-projects

The length of time it takes depends on the number of packages in the source. Change the first line in GeneratePackages.ps1 to $generateFewerPackages = true to see that it complete in shorter time (provided you don't have the full list of packages generated before). demo-projects.zip

Graph of dependencies:

graph TD;
    A-->B;
    A-->C;
    B-->D;
    C-->D;
    D-->E

pauby commented 1 month ago

We need to reproduce your issue. The one you reported. Do you have 1000 packages in your repository, with inter-related dependencies, that are causing you day-to-day issues?

What you've provided is a script to create up to 1000 packages with inter-related dependencies. This isn't a real-world use case and feels more hypothetical. If you have this in your repository, it's going to take a while to resolve.

Chocolatey CLI uses NuGet libraries for package and dependency resolution, as you saw, so this would be better raised with them.

josh-cooley commented 1 month ago

Yes. We have packages with inter-related dependencies and push builds to an artifact server. The head package that pulls in all the dependencies is pushed twice daily, but the middle packages can be pushed more often than that. It is far from hypothetical, but is instead a simplified version of what we have.

josh-cooley commented 1 month ago

We have multiple packages for services. Each change a developer commits may update the configuration package and/or the service package. These are deployed continuously with automated testing and we can gather a very large number of package versions since they are generated with each build. There is also a tools package that is not versioned very often. It has a dependency on some parts of these packages. Twice a day we generate a master package that can be used to pull in all packages through dependencies. This generates the diamond pattern for dependencies.

I've been able to resolve this with a build of the choco source, but I'm uncertain of the implications of checking the dependency cache this way vs a regular .Contains call (see line 12 of each file). NugetCommon.HandleDependencies change

I see that the NuGet libraries are used for dependency resolution, but my hope is that the cache that is used currently can catch this case to avoid additional dependency checks.

pauby commented 1 month ago

Following the instructions in this comment, the packages were installed in 2m 24s using Chocolatey CLI v2.2.2.

This is a second run (after resetting the VM) without --verbose so you can see the full console. Installed in 2m 32s.

josh-cooley commented 1 month ago

The local disk installs are significantly faster. When I run it with the fewer packages option I see an install of 2.991 seconds. There's a multiplier effect with the number of packages available and fetching those over the network is how you reach the times initially reported. I apologize if the comment showing the disk install was misleading. I meant to use it as a quick example showing slower installs. If you want to see extreme times, you would need a package server with http access. I'm looking into your suggestion on how the NuGet libraries handle this. Running nuget.exe install with the -outputdirectory option pulls all dependencies much faster, so there must be some option they are taking advantage of to resolve dependencies.

josh-cooley commented 1 month ago

I think I understand how the nuget.exe is avoiding this problem. For context, I'm looking at the following classes:

NuGetPackageManager
ResolverGather
PackageResolver

The key is in ResolverGather. It pulls in the primary target and finds its dependencies. A closure is built in a loop over the parent and child packages based on the Dependencies property of a SourcePackageDependencyInfo. This is projected down to just the package ids. Any packages that have not been searched by id goes through the dependency load again.

The method used to find dependency information is DependencyInfoResource.ResolvePackages just like in the GetPackageDependencies method in NugetCommon (from chocolatey project). The difference is that the nuget client code will only call ResolvePackages once per id. My proposed fix considers the dependency VersionRange. Since ResolvePackages doesn't take version info, this may not be necessary. The key to avoiding the problem is reducing duplicate calls to ResolvePackages.

pauby commented 1 month ago

Will this issue be fixed by #3433 ?

josh-cooley commented 1 month ago

3433 looks to be a very similar issue, but the fix was not sufficient for this issue. I'm able to reproduce the slow resolution of packages with a build from the develop branch.

HandleDependencies was added for #3433, and the GetPackageDependencies call in the else case doesn't consider the version info until after calling ResolvePackages. If version information is not considered in ResolvePackages, the cache will have more information than is being considered in HandleDependencies. The cache test works well for the first case in HandleDependencies, but should be more expansive for the second.

josh-cooley commented 3 weeks ago

I'm looking at the contributor requirements to offer up a possible solution. In the mean time, I'll offer this observation. GetPackageDependencies that takes a PackageIdentity uses availablePackages to avoid network requests if the results are already available. GetPackageDependencies that takes a packageId string needs to avoid duplicate network requests and could use availablePackages as well.

chocolatey / choco

Dependency resolution during install can be slow #3451

Checklist

What You Are Seeing?

What is Expected?

How Did You Get This To Happen?

System Details

Installed Packages

Output Log

Additional Context

3433 looks to be a very similar issue, but the fix was not sufficient for this issue. I'm able to reproduce the slow resolution of packages with a build from the develop branch.