SQL Server execution timeouts after updating to 2023.31 (Build 5)

[appplat_4310]

Hi, yesterday we updated to the latest available Proget version and after that we started to see this error in the logs:

An error occurred processing a GET request to https://nuget.ges.ferlan.it/nuget/default/FindPackagesById()?id='Humanizer.Core.uz-Latn-UZ'&semVerLevel=2.0.0: Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.

Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
---> System.ComponentModel.Win32Exception (258): The wait operation timed out.
at Microsoft.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__209_0(Task`1 result)
at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
at Inedo.Data.DatabaseContext.DbResult.CreateAsync(DbCommand command, DatabaseContext context, DateTimeOffset startTime, Stopwatch stopwatch)
at Inedo.Data.DatabaseContext.ExecuteInternalAsync(String storedProcName, GenericDbParameter[] parameters)
at Inedo.Data.SqlServerDatabaseContext.ExecuteInternalAsync(String storedProcName, GenericDbParameter[] parameters)
at Inedo.Data.DatabaseContext.ExecuteTableAsync[TRow](String storedProcName, GenericDbParameter[] parameters)
at Inedo.ProGet.Feeds.NuGet.V2.LocalPackageSource.FindPackagesByIdAsync(NuGetQueryOptions options, String id)
at Inedo.ProGet.Feeds.NuGet.NuGetFeed.FindPackagesByIdAsync(NuGetQueryOptions options, String id)
at Inedo.ProGet.WebApplication.FeedEndpoints.NuGet.ODataQueryHandler.FindPackagesById(String id)
at Inedo.ProGet.WebApplication.FeedEndpoints.NuGet.ODataHandler.ProcessVirtualRequestAsync(ODataResponseContext context, NuGetFeed feed, String relativeUrl)
at Inedo.ProGet.WebApplication.FeedEndpoints.NuGet.ODataHandler.ProcessRequestAsync(AhHttpContext context, WebApiContext apiContext, NuGetFeed feed, String relativeUrl)
at Inedo.ProGet.WebApplication.FeedEndpoints.NuGet.NuGetFeedHandler.ProcessRequestAsync(AhHttpContext context, WebApiContext apiContext, NuGetFeed feed, String relativeUrl)
at Inedo.ProGet.WebApplication.FeedEndpoints.FeedEndpointHandler.FeedRequestHandler.ProcessRequestAsync(AhHttpContext context)
ClientConnectionId:f32aa96d-5f9a-4b04-8696-6af4f1a92b03
Error Number:-2,State:0,Class:11

This is happening with multiple packages, not just the one in the example. Multiple times a day:

This request is putting a strain in the SQL server where we see high CPU usage on the Proget DB. This is the query causing a very high CPU usage:

SELECT *
	  FROM [NuGetFeedPackageVersions_Extended] 
	 WHERE [Feed_Id] = @Feed_Id
	   AND [Package_Name_Lower] = LOWER(@Package_Id)
	   AND (@Version_Text IS NULL OR [Package_Version] = @Version_Text)

Maybe the last line is the issue?
Any help is much appreciated.
Thanks

[appplat_4310]

This post is deleted!

[appplat_4310]

We thought that the error was caused by another DB using a lot of CPU on the same SQL Server but in fact the problem is still there and was not caused by that.
Is there anything that we can do to help you trubleshoot this issue that we are having?

[atripp]

Hi @appplat_4310 ,

In 2023.31, we made made introduced various database performance improvements (deadlock, timeout reductions) via PG-2606, so it's possibly related to that. The query you identified most definitely helped, and it there's only one place it's called.

WE would be super-grateful if you could try running this?

ALTER PROCEDURE [NuGet_GetPackage]
(
	@Feed_Id INT,
	@Package_Id VARCHAR(255),
	@Version_Text VARCHAR(255) = NULL
)
AS
BEGIN

	SET NOCOUNT ON

	SELECT *
	  FROM [NuGetFeedPackageVersions_Extended] 
	 WHERE [Feed_Id] = @Feed_Id
	   AND [PackageGroup_Name] IS NULL
	   AND [PackageType_Name] = 'nuget'
	   AND [Package_Name_Lower] = LOWER(@Package_Id)
	   AND (@Version_Text IS NULL OR [Package_Version] = @Version_Text)
END

We believe that, for some reason, your query analyzer is following a different plan, but the new conditionals should force it to use the right index.

Let us know, and we'll get it fixed right away.

Thanks,
Alana

[appplat_4310]

Hi @atripp ,
we applied the alter of the procedure, at the moment everything looks fine and the CPU performance on the SQL server seems back to a normal usage. I'll keep you posted to confirm if everything goes well for a day or two.

Thanks

[appplat_4310]

Hi, I can confirm that now the CPU usage is stabilized and we don't have errors in the Proget logs. To be fair we also addeed some storage and retention rules that have cleaned up a lot of our feeds (we purged about 50-60% of the cached packages) and probably this helped too.

[atripp]

@appplat_4310 thanks for the update!

We also applied the patch to the next maintenance release, so you shouldn't have any issues going forward then!