Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Possible memory leak in combination with EfCore #899

Open
ArnaudB88 opened this issue Nov 5, 2024 · 1 comment
Open

Possible memory leak in combination with EfCore #899

ArnaudB88 opened this issue Nov 5, 2024 · 1 comment
Labels
bug Issues describing a bug or pull requests fixing a bug.

Comments

@ArnaudB88
Copy link

ArnaudB88 commented Nov 5, 2024

Describe the bug

I recently added your library to a large .NET solution. Since the library was added, we get memory increases on the production environment a few times a month. The memory increases till the maximum resulting in a frozen web API.

Steps to reproduce

  1. Configure a serilogger with the exception enricher
  2. specify the serilogger as EfCore dbcontext logger
  3. execute some db changes which fail
  4. possible memory leak occurs (I guess because of the ReflectionBasedDestructurer)

Expected behaviour

I expect no memory increase.

Our code

Serilogger

var logger = new LoggerConfiguration()
    .Enrich.WithDemystifiedStackTraces() //Cleaner stacktrace
    .Enrich.WithExceptionDetails() //More exception details
    .MinimumLevel.Information()//Limit to information since debug results in too much db logs
    .WriteTo.Trace(outputTemplate: outputTemplate) //write all msgs to trace
    .CreateLogger();

EfCore dbcontext

var debugLoggerFactory = LoggerFactory.Create(builder =>
{
    builder.AddSerilog(context.GetInstance<Serilog.ILogger>(Constants.SerilogForTrace)); //the logger configured above
});

var optionsBuilder = new DbContextOptionsBuilder<EntityFrameworkEntitiesDbContext>();
optionsBuilder
    .UseLazyLoadingProxies() //https://docs.microsoft.com/en-us/ef/core/querying/related-data/lazy
    .UseSqlServer(connectionString, sqlServerOptions => sqlServerOptions.CommandTimeout(60))
    .UseLoggerFactory(debugLoggerFactory)
    .EnableSensitiveDataLogging()
    .EnableDetailedErrors();
var dbContext = new DbContext (optionsBuilder.Options);

Application insights information

Two examples from the 'Code optimizations'

Example 1

Description: Too much CPU/Memory is being spent in logging.

Current condition: 50% of your Memory was spent in ```````````SerilogLogger.Log``````````` called from ```````````Microsoft.EntityFrameworkCore.Diagnostics.EventDefinition.Log```````````. We expected this value to be <20%.

Recommendations: Check logging levels and reduce the volume of logs in production. Consider tweaking level for each category. Also consider high performance logging (Reference: https://aka.ms/AAfkq94).

Call Stack:

0. serilog.exceptions!Serilog.Exceptions.Destructurers.ReflectionBasedDestructurer.Destructure(class System.Exception,class Serilog.Exceptions.Core.IExceptionPropertiesBag,class System.Func`2<class System.Exception,class System.Collections.Generic.IReadOnlyDictionary`2<class System.String,class System.Object>>)
1. serilog.exceptions!Serilog.Exceptions.Core.ExceptionEnricher.DestructureException(class System.Exception)
2. serilog.exceptions!Serilog.Exceptions.Core.ExceptionEnricher.Enrich(class Serilog.Events.LogEvent,class Serilog.Core.ILogEventPropertyFactory)
3. serilog!Serilog.Core.Enrichers.SafeAggregateEnricher.Enrich(class Serilog.Events.LogEvent,class Serilog.Core.ILogEventPropertyFactory)
4. serilog!Serilog.Core.Logger.Dispatch(class Serilog.Events.LogEvent)
5. serilog.extensions.logging!Serilog.Extensions.Logging.SerilogLogger.Log(value class Microsoft.Extensions.Logging.LogLevel,value class Microsoft.Extensions.Logging.EventId,!!0,class System.Exception,class System.Func`3<!!0,class System.Exception,class System.String>)
6. serilog.extensions.logging!dynamicClass.IL_STUB_InstantiatingStub(pMT: 00007FFDA03381A0,pMT: 00007FFDA2022788,pMT: 00007FFDACB08510,pMT: 00007FFDA0020820,pMT: 00007FFDA01A49F0<pMT: 00007FFDACB08510,pMT: 00007FFDA0020820,class System.String>)
7. microsoft.extensions.logging.il!Microsoft.Extensions.Logging.Logger.<Log>g__LoggerLog|14_0(value class Microsoft.Extensions.Logging.LogLevel,value class Microsoft.Extensions.Logging.EventId,class Microsoft.Extensions.Logging.ILogger,class System.Exception,class System.Func`3<!!0,class System.Exception,class System.String>,class System.Collections.Generic.List`1<class System.Exception>&,!!0&)
8. microsoft.extensions.logging.il!Microsoft.Extensions.Logging.Logger.Log(value class Microsoft.Extensions.Logging.LogLevel,value class Microsoft.Extensions.Logging.EventId,!!0,class System.Exception,class System.Func`3<!!0,class System.Exception,class System.String>)
9. microsoft.extensions.logging.il!dynamicClass.IL_STUB_InstantiatingStub(pMT: 00007FFDA03381A0,pMT: 00007FFDA2022788,pMT: 00007FFDACB08510,pMT: 00007FFDA0020820,pMT: 00007FFDA01A49F0<pMT: 00007FFDACB08510,pMT: 00007FFDA0020820,class System.String>)
10. microsoft.extensions.logging.abstractions!Microsoft.Extensions.Logging.LoggerMessage+<>c__DisplayClass14_0`3[System.__Canon, System.__Canon, System.__Canon]::<Define>g__Log|0(Microsoft.Extensions.Logging.ILogger, System.__Canon, System.__Canon, System.__Canon, System.Exception)
11. microsoft.entityframeworkcore!Microsoft.EntityFrameworkCore.Diagnostics.EventDefinition`3[System.__Canon,System.__Canon,System.__Canon].Log(class Microsoft.EntityFrameworkCore.Diagnostics.IDiagnosticsLogger`1<!!0>,!0,!1,!2,class System.Exception)
12. microsoft.entityframeworkcore!dynamicClass.IL_STUB_InstantiatingStub(pMT: 00007FFDA32DD728<pMT: 00007FFDA30B1BE0>,pMT: 00007FFD9FED8BE8,pMT: 00007FFD9FF8EC08,pMT: 00007FFDA0020820,pMT: 00007FFDA0020820)
13. microsoft.entityframeworkcore!Microsoft.EntityFrameworkCore.Diagnostics.CoreLoggerExtensions.SaveChangesFailedAsync(class Microsoft.EntityFrameworkCore.Diagnostics.IDiagnosticsLogger`1<class Update>,class Microsoft.EntityFrameworkCore.DbContext,class System.Exception,value class System.Threading.CancellationToken)
14. microsoft.entityframeworkcore!Microsoft.EntityFrameworkCore.DbContext+<SaveChangesAsync>d__63.MoveNext()
15. system.private.corelib.il!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[System.Int32,Microsoft.EntityFrameworkCore.DbContext+<SaveChangesAsync>d__63].ExecutionContextCallback(class System.Object)
16. system.private.corelib.il!System.Threading.ExecutionContext.RunInternal(class System.Threading.ExecutionContext,class System.Threading.ContextCallback,class System.Object)

Example 2

Description: `EntityEntry.get_Navigations` is causing unusually high memory allocations.

Current condition: 33% of your Memory was spent in ```````````EntityEntry.get_Navigations``````````` called from ```````````Serilog.Exceptions.Destructurers.ReflectionBasedDestructurer.DestructureValueEnumerable```````````. We expected this value to be <11%.

Recommendations: Consider investigating why `EntityEntry.get_Navigations` is causing higher than expected memory allocations.
<br />NOTE: We are currently working on refining the details of this recommendation. In the meantime please click [here](https://aka.ms/profiler/perflens/recommendation/memory) to get general information about memory performance optimization.

Call Stack:

0. microsoft.entityframeworkcore!Microsoft.EntityFrameworkCore.ChangeTracking.Internal.ChangeDetector.LocalDetectChanges(class Microsoft.EntityFrameworkCore.ChangeTracking.Internal.InternalEntityEntry)
1. microsoft.entityframeworkcore!Microsoft.EntityFrameworkCore.ChangeTracking.Internal.ChangeDetector.DetectChanges(class Microsoft.EntityFrameworkCore.ChangeTracking.Internal.InternalEntityEntry,class System.Collections.Generic.HashSet`1<class Microsoft.EntityFrameworkCore.ChangeTracking.Internal.InternalEntityEntry>)
2. microsoft.entityframeworkcore!Microsoft.EntityFrameworkCore.ChangeTracking.Internal.ChangeDetector.DetectChanges(class Microsoft.EntityFrameworkCore.ChangeTracking.Internal.InternalEntityEntry,class System.Collections.Generic.HashSet`1<class Microsoft.EntityFrameworkCore.ChangeTracking.Internal.InternalEntityEntry>)
3. microsoft.entityframeworkcore!Microsoft.EntityFrameworkCore.ChangeTracking.Internal.ChangeDetector.DetectChanges(class Microsoft.EntityFrameworkCore.ChangeTracking.Internal.InternalEntityEntry)
4. microsoft.entityframeworkcore!Microsoft.EntityFrameworkCore.ChangeTracking.CollectionEntry.LocalDetectChanges()
5. microsoft.entityframeworkcore!Microsoft.EntityFrameworkCore.ChangeTracking.EntityEntry.<get_Navigations>b__25_0(class Microsoft.EntityFrameworkCore.Metadata.INavigationBase)
6. system.linq.il!System.Linq.Enumerable+SelectEnumerableIterator`2[System.__Canon,System.__Canon].MoveNext()
7. serilog.exceptions!Serilog.Exceptions.Destructurers.ReflectionBasedDestructurer.DestructureValueEnumerable(class System.Collections.IEnumerable,int32,class System.Collections.Generic.IDictionary`2<class System.Object,class System.Collections.Generic.IDictionary`2<class System.String,class System.Object>>,int32&)
8. serilog.exceptions!Serilog.Exceptions.Destructurers.ReflectionBasedDestructurer.DestructureObject(class System.Object,class System.Type,int32,class System.Collections.Generic.IDictionary`2<class System.Object,class System.Collections.Generic.IDictionary`2<class System.String,class System.Object>>,int32&)
9. serilog.exceptions!Serilog.Exceptions.Destructurers.ReflectionBasedDestructurer.DestructureObject(class System.Object,class System.Type,int32,class System.Collections.Generic.IDictionary`2<class System.Object,class System.Collections.Generic.IDictionary`2<class System.String,class System.Object>>,int32&)
10. serilog.exceptions!Serilog.Exceptions.Destructurers.ReflectionBasedDestructurer.DestructureValueEnumerable(class System.Collections.IEnumerable,int32,class System.Collections.Generic.IDictionary`2<class System.Object,class System.Collections.Generic.IDictionary`2<class System.String,class System.Object>>,int32&)
11. serilog.exceptions!Serilog.Exceptions.Destructurers.ReflectionBasedDestructurer.DestructureObject(class System.Object,class System.Type,int32,class System.Collections.Generic.IDictionary`2<class System.Object,class System.Collections.Generic.IDictionary`2<class System.String,class System.Object>>,int32&)
12. serilog.exceptions!Serilog.Exceptions.Destructurers.ReflectionBasedDestructurer.DestructureObject(class System.Object,class System.Type,int32,class System.Collections.Generic.IDictionary`2<class System.Object,class System.Collections.Generic.IDictionary`2<class System.String,class System.Object>>,int32&)
@ArnaudB88 ArnaudB88 added the bug Issues describing a bug or pull requests fixing a bug. label Nov 5, 2024
@ArnaudB88
Copy link
Author

Possibly related to #898

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Issues describing a bug or pull requests fixing a bug.
Projects
None yet
Development

No branches or pull requests

1 participant