RelationalDatabaseFacadeExtensions.GetFacadeDependencies is causing unusually high memory allocations

[mhkolk]

Bug description

Using EF Core in ASP.NET Core application with Azure Monitor Open Telemetry / Application Insights enabled this is the top issue reported in the Performance section of App Insights console on Azure Portal:

Description
RelationalDatabaseFacadeExtensions.GetFacadeDependencies is causing unusually high memory allocations.

Condition
26% of your Memory was spent in RelationalDatabaseFacadeExtensions.GetFacadeDependencies called from TimeSeries.Data.DataService.InsertTimeSeriesValuesQueryAsync. We expected this value to be <12%.

Recommendation
Consider investigating why RelationalDatabaseFacadeExtensions.GetFacadeDependencies is causing higher than expected memory allocations.

Your code

public async Task SaveTimeSeriesValuesAsync(List<TimeSeriesValueCreateRequest> timeSeriesCreateRequests)
	{
		try
		{
			var tsValueUpsertList = new List<TSTimeSeriesValue>();

			foreach (var inputDTO in timeSeriesCreateRequests)
			{
				//VALIDATOR
				//await _modelValidationService.ValidateAsync(inputDTO);

				if (inputDTO.TimeSeriesId.HasValue)
				{
					await ValidateTimeSeriesIdAsync(inputDTO.TimeSeriesId.Value);
				}

				Guid timeSeriesId = inputDTO.TimeSeriesId.HasValue
								? inputDTO.TimeSeriesId.Value
								: await GetTimeSeriesIdByNameAsync(inputDTO.TimeSeriesName!);

				foreach (var timeSeriesValueInput in inputDTO.TimeSeriesValueInputs)
				{

					var newTimeSeriesValue = new TSTimeSeriesValue()
					{
						IdTimeSeries = timeSeriesId,
						DateTimeTick = timeSeriesValueInput.DateTimeTick!.Value.UtcDateTime,
						DateTimeValue = timeSeriesValueInput.DateTimeValue!.Value.UtcDateTime,
						DateTimeToValue = timeSeriesValueInput.DateTimeToValue?.UtcDateTime,
						NumericValue = timeSeriesValueInput.NumericValue,
						JsonValue = timeSeriesValueInput.JsonValue
					};

					tsValueUpsertList.Add(newTimeSeriesValue);
				}
			}

			if (tsValueUpsertList.Count == 0) return;

			try
			{
				//Batch insert has parameter limit of 65535 - currently we have 6 parameters for each insert
				int valueParameterLimit = 10000;
				if (tsValueUpsertList.Count > valueParameterLimit)
				{
					int skip = 0;
					while (true)
					{
						var tsValueUpsertListPartial = tsValueUpsertList.Skip(skip).Take(valueParameterLimit).ToList();

						if (tsValueUpsertListPartial.Count == 0) break;

						InsertTimeSeriesValuesQueryAsync(tsValueUpsertListPartial);

						skip += valueParameterLimit;
					}
				}
				else
				{
					InsertTimeSeriesValuesQueryAsync(tsValueUpsertList);
				}
			}
			catch (Exception e)
			{
				CheckDuplicateException(e, timeSeriesCreateRequests, tsValueUpsertList);
				throw;
			}
		}
		catch (Exception e)
		{
			_logger.LogError(@$"SaveTimeSeriesValuesAsync; Exception: {e.Message}; Inner Exception: {e.InnerException}; StackTrace: {e.StackTrace}");
			throw;
		}
	}

Stack traces

Microsoft.Extensions.DependencyInjection!dynamicClass.ResolveService(pMT: 0x7f379acd60b0,pMT: 0x7f379aa82ae8)
Microsoft.Extensions.DependencyInjection.Abstractions!Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService(class System.IServiceProvider,class System.Type)
Microsoft.Extensions.DependencyInjection.Abstractions!Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService(class System.IServiceProvider)
Microsoft.EntityFrameworkCore!Microsoft.EntityFrameworkCore.DbContext.get_ContextServices()
Microsoft.EntityFrameworkCore!Microsoft.EntityFrameworkCore.Infrastructure.Internal.InfrastructureExtensions.GetService(class Microsoft.EntityFrameworkCore.Infrastructure.IInfrastructure`1<class System.IServiceProvider>,class System.Type)
Microsoft.EntityFrameworkCore.Relational!Microsoft.EntityFrameworkCore.RelationalDatabaseFacadeExtensions.GetFacadeDependencies(class Microsoft.EntityFrameworkCore.Infrastructure.DatabaseFacade) --> EXCESSIVE USAGE
TimeSeries!TimeSeries.Data.DataService.InsertTimeSeriesValuesQueryAsync(class System.Collections.Generic.List`1<class Common.Data.TimeSeriesNS.TSTimeSeriesValue>)
TimeSeries!TimeSeries.Data.DataService+<SaveTimeSeriesValuesAsync>d__15.MoveNext()
System.Private.CoreLib!System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start(!!0&)
TimeSeries!TimeSeries.TimeSeriesNS.TimeSeriesController+<SaveTimeSeriesValues>d__16.MoveNext()
System.Private.CoreLib!System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start(!!0&)
TimeSeries!TimeSeries.TimeSeriesNS.TimeSeriesController.SaveTimeSeriesValues(class System.Collections.Generic.List`1<class TimeSeries.TimeSeriesNS.TimeSeriesValueCreateRequest>)

Verbose output

EF Core version

8.0.15

Database provider

Npgsql

Target framework

.NET 8

Operating system

Running in AKS

IDE

No response

[roji]

This is very unilkely to be about RelationalDatabaseFacadeExtensions.GetFacadeDependenciesm, it's probably the first real call on the DbContext and causes all services to get set up etc.

Are you using DbContext pooling? If not, can you please turn that on and check on the results?

[mhkolk]

This required to introduce DbContext pooling into codebase, now it will take some time to redeploy and monitor a couple of weeks. Will let you know of results.

[roji]

@mhkolk in that case, I'll go ahead and close this issue for now - but that only means we don't have a currently-confirmed problem. Once you have the results, please post back here and we'll reopen if necessary.

[mhkolk]

After some 24 hours it appears the introduction of DbContext pooling resolved the reported Azure App Insights problem with excessive memory allocations - the problem is not being reported anymore.

However, it will be tough to introduce pooling everywhere because we use multitenancy and we also use HttpContextAccessor in some of our DbContexts.

[roji]

@mhkolk great to hear, thanks for posting back!

We've got guidance on how to do DbContext pooling with context state (e.g. multitenancy), so that hopefully shouldn't be an issue. It's highly recommended to switch to DbContext pooling wherever possible.