search

RehanSaeed / Serilog.Exceptions

Log exception details and custom properties that are not output in Exception.ToString().
MIT License
514 stars 52 forks source link

Possible memory leak in combination with EfCore #899

Open ArnaudB88 opened 2 weeks ago

ArnaudB88 commented 2 weeks ago

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 commented 2 weeks ago

Possibly related to #898