Merge pull request #247 from nblumhardt/serilog-4x

Remove some allocations

Author: nblumhardt

serilog-extensions-logging.sln.DotSettings

@@ -1,2 +1,3 @@
 <wpf:ResourceDictionary xml:space="preserve" xmlns:x="http://schemas.microsoft.com/winfx/2006/xaml" xmlns:s="clr-namespace:System;assembly=mscorlib" xmlns:ss="urn:shemas-jetbrains-com:settings-storage-xaml" xmlns:wpf="http://schemas.microsoft.com/winfx/2006/xaml/presentation">
+	<s:Boolean x:Key="/Default/UserDictionary/Words/=enricher/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=stringified/@EntryIndexedValue">True</s:Boolean></wpf:ResourceDictionary>

src/Serilog.Extensions.Logging/Extensions/Logging/EventIdPropertyCache.cs

@@ -21,7 +21,7 @@ namespace Serilog.Extensions.Logging;
 sealed class EventIdPropertyCache
 {
     readonly int _maxCachedProperties;
-    readonly ConcurrentDictionary<EventKey, LogEventProperty> _propertyCache = new();
+    readonly ConcurrentDictionary<EventKey, LogEventPropertyValue> _propertyCache = new();
 
     int _count;
 
@@ -30,32 +30,32 @@ public EventIdPropertyCache(int maxCachedProperties = 1024)
         _maxCachedProperties = maxCachedProperties;
     }
 
-    public LogEventProperty GetOrCreateProperty(in EventId eventId)
+    public LogEventPropertyValue GetOrCreatePropertyValue(in EventId eventId)
     {
         var eventKey = new EventKey(eventId);
 
-        LogEventProperty? property;
+        LogEventPropertyValue? propertyValue;
 
         if (_count >= _maxCachedProperties)
         {
-            if (!_propertyCache.TryGetValue(eventKey, out property))
+            if (!_propertyCache.TryGetValue(eventKey, out propertyValue))
             {
-                property = CreateProperty(in eventKey);
+                propertyValue = CreatePropertyValue(in eventKey);
             }
         }
         else
         {
-            if (!_propertyCache.TryGetValue(eventKey, out property))
+            if (!_propertyCache.TryGetValue(eventKey, out propertyValue))
             {
                 // GetOrAdd is moved to a separate method to prevent closure allocation
-                property = GetOrAddCore(in eventKey);
+                propertyValue = GetOrAddCore(in eventKey);
             }
         }
 
-        return property;
+        return propertyValue;
     }
 
-    static LogEventProperty CreateProperty(in EventKey eventKey)
+    static LogEventPropertyValue CreatePropertyValue(in EventKey eventKey)
     {
         var properties = new List<LogEventProperty>(2);
 
@@ -69,17 +69,17 @@ static LogEventProperty CreateProperty(in EventKey eventKey)
             properties.Add(new LogEventProperty("Name", new ScalarValue(eventKey.Name)));
         }
 
-        return new LogEventProperty("EventId", new StructureValue(properties));
+        return new StructureValue(properties);
     }
 
-    LogEventProperty GetOrAddCore(in EventKey eventKey) =>
+    LogEventPropertyValue GetOrAddCore(in EventKey eventKey) =>
         _propertyCache.GetOrAdd(
             eventKey,
             key =>
             {
                 Interlocked.Increment(ref _count);
 
-                return CreateProperty(in key);
+                return CreatePropertyValue(in key);
             });
 
     readonly record struct EventKey

src/Serilog.Extensions.Logging/Extensions/Logging/LevelConvert.cs

@@ -36,7 +36,8 @@ public static LogEventLevel ToSerilogLevel(LogLevel logLevel)
     {
         return logLevel switch
         {
-            LogLevel.None or LogLevel.Critical => LogEventLevel.Fatal,
+            LogLevel.None => LevelAlias.Off,
+            LogLevel.Critical => LogEventLevel.Fatal,
             LogLevel.Error => LogEventLevel.Error,
             LogLevel.Warning => LogEventLevel.Warning,
             LogLevel.Information => LogEventLevel.Information,

src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs

@@ -89,30 +89,33 @@ LogEvent PrepareWrite<TState>(LogEventLevel level, EventId eventId, TState state
     {
         string? messageTemplate = null;
 
-        var properties = new List<LogEventProperty>();
+        var properties = new Dictionary<string, LogEventPropertyValue>();
 
         if (state is IEnumerable<KeyValuePair<string, object>> structure)
         {
             foreach (var property in structure)
             {
-                if (property.Key == SerilogLoggerProvider.OriginalFormatPropertyName && property.Value is string value)
+                if (property is { Key: SerilogLoggerProvider.OriginalFormatPropertyName, Value: string value })
                 {
                     messageTemplate = value;
                 }
                 else if (property.Key.StartsWith('@'))
                 {
                     if (_logger.BindProperty(GetKeyWithoutFirstSymbol(DestructureDictionary, property.Key), property.Value, true, out var destructured))
-                        properties.Add(destructured);
+                        properties[destructured.Name] = destructured.Value;
                 }
                 else if (property.Key.StartsWith('$'))
                 {
                     if (_logger.BindProperty(GetKeyWithoutFirstSymbol(StringifyDictionary, property.Key), property.Value?.ToString(), true, out var stringified))
-                        properties.Add(stringified);
+                        properties[stringified.Name] = stringified.Value;
                 }
                 else
                 {
-                    if (_logger.BindProperty(property.Key, property.Value, false, out var bound))
-                        properties.Add(bound);
+                    // Simple micro-optimization for the most common and reliably scalar values; could go further here.
+                    if (property.Value is null or string or int or long && LogEventProperty.IsValidName(property.Key))
+                        properties[property.Key] = new ScalarValue(property.Value);
+                    else if (_logger.BindProperty(property.Key, property.Value, false, out var bound))
+                        properties[bound.Name] = bound.Value;
                 }
             }
 
@@ -123,7 +126,7 @@ LogEvent PrepareWrite<TState>(LogEventLevel level, EventId eventId, TState state
             {
                 messageTemplate = "{" + stateType.Name + ":l}";
                 if (_logger.BindProperty(stateType.Name, AsLoggableValue(state, formatter), false, out var stateTypeProperty))
-                    properties.Add(stateTypeProperty);
+                    properties[stateTypeProperty.Name] = stateTypeProperty.Value;
             }
         }
 
@@ -146,19 +149,20 @@ LogEvent PrepareWrite<TState>(LogEventLevel level, EventId eventId, TState state
             if (propertyName != null)
             {
                 if (_logger.BindProperty(propertyName, AsLoggableValue(state, formatter!), false, out var property))
-                    properties.Add(property);
+                    properties[property.Name] = property.Value;
             }
         }
 
+        // The overridden `!=` operator on this type ignores `Name`.
         if (eventId.Id != 0 || eventId.Name != null)
-            properties.Add(_eventIdPropertyCache.GetOrCreateProperty(in eventId));
+            properties.Add("EventId", _eventIdPropertyCache.GetOrCreatePropertyValue(in eventId));
 
         var (traceId, spanId) = Activity.Current is { } activity ?
             (activity.TraceId, activity.SpanId) :
             (default(ActivityTraceId), default(ActivitySpanId));
 
-        var parsedTemplate = MessageTemplateParser.Parse(messageTemplate ?? "");
-        return new LogEvent(DateTimeOffset.Now, level, exception, parsedTemplate, properties, traceId, spanId);
+        var parsedTemplate = messageTemplate != null ? MessageTemplateParser.Parse(messageTemplate) : MessageTemplate.Empty;
+        return LogEvent.UnstableAssembleFromParts(DateTimeOffset.Now, level, exception, parsedTemplate, properties, traceId, spanId);
     }
 
     static object? AsLoggableValue<TState>(TState state, Func<TState, Exception?, string>? formatter)

src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs

@@ -51,25 +51,6 @@ public void Dispose()
 
     public static void EnrichWithStateAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, object? state, out LogEventPropertyValue? scopeItem)
     {
-        void AddProperty(string key, object? value)
-        {
-            var destructureObject = false;
-
-            if (key.StartsWith('@'))
-            {
-                key = SerilogLogger.GetKeyWithoutFirstSymbol(SerilogLogger.DestructureDictionary, key);
-                destructureObject = true;
-            }
-            else if (key.StartsWith('$'))
-            {
-                key = SerilogLogger.GetKeyWithoutFirstSymbol(SerilogLogger.StringifyDictionary, key);
-                value = value?.ToString();
-            }
-
-            var property = propertyFactory.CreateProperty(key, value, destructureObject);
-            logEvent.AddPropertyIfAbsent(property);
-        }
-
         if (state == null)
         {
             scopeItem = null;
@@ -79,52 +60,64 @@ void AddProperty(string key, object? value)
         // Eliminates boxing of Dictionary<TKey, TValue>.Enumerator for the most common use case
         if (state is Dictionary<string, object> dictionary)
         {
-            scopeItem = null; // Unless it's `FormattedLogValues`, these are treated as property bags rather than scope items.
-
+            // Separate handling of this case eliminates boxing of Dictionary<TKey, TValue>.Enumerator.
+            scopeItem = null;
             foreach (var stateProperty in dictionary)
-            {
-                if (stateProperty.Key == SerilogLoggerProvider.OriginalFormatPropertyName && stateProperty.Value is string)
-                    scopeItem = new ScalarValue(state.ToString());
-                else
-                    AddProperty(stateProperty.Key, stateProperty.Value);
+            {                
+                AddProperty(logEvent, propertyFactory, stateProperty.Key, stateProperty.Value);
             }
         }
         else if (state is IEnumerable<KeyValuePair<string, object>> stateProperties)
         {
-            scopeItem = null; // Unless it's `FormattedLogValues`, these are treated as property bags rather than scope items.
-
+            scopeItem = null;
             foreach (var stateProperty in stateProperties)
             {
-                if (stateProperty.Key == SerilogLoggerProvider.OriginalFormatPropertyName && stateProperty.Value is string)
+                if (stateProperty is { Key: SerilogLoggerProvider.OriginalFormatPropertyName, Value: string })
+                {
+                    // `_state` is most likely `FormattedLogValues` (a MEL internal type).
                     scopeItem = new ScalarValue(state.ToString());
+                }
                 else
-                    AddProperty(stateProperty.Key, stateProperty.Value);
+                {
+                    AddProperty(logEvent, propertyFactory, stateProperty.Key, stateProperty.Value);
+                }
             }
         }
 #if FEATURE_ITUPLE
         else if (state is System.Runtime.CompilerServices.ITuple tuple && tuple.Length == 2 && tuple[0] is string s)
         {
             scopeItem = null; // Unless it's `FormattedLogValues`, these are treated as property bags rather than scope items.
-
-            if (s == SerilogLoggerProvider.OriginalFormatPropertyName && tuple[1] is string)
-                scopeItem = new ScalarValue(state.ToString());
-            else
-                AddProperty(s, tuple[1]);
+            AddProperty(logEvent, propertyFactory, s, tuple[1]);
         }
 #else
         else if (state is ValueTuple<string, object?> tuple)
         {
-            scopeItem = null; // Unless it's `FormattedLogValues`, these are treated as property bags rather than scope items.
-
-            if (tuple.Item1 == SerilogLoggerProvider.OriginalFormatPropertyName && tuple.Item2 is string)
-                scopeItem = new ScalarValue(state.ToString());
-            else
-                AddProperty(tuple.Item1, tuple.Item2);
+            scopeItem = null;
+            AddProperty(logEvent, propertyFactory, tuple.Item1, tuple.Item2);
         }
 #endif
         else
         {
             scopeItem = propertyFactory.CreateProperty(NoName, state).Value;
         }
     }
+
+    static void AddProperty(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, string key, object? value)
+    {
+        var destructureObject = false;
+
+        if (key.StartsWith('@'))
+        {
+            key = SerilogLogger.GetKeyWithoutFirstSymbol(SerilogLogger.DestructureDictionary, key);
+            destructureObject = true;
+        }
+        else if (key.StartsWith('$'))
+        {
+            key = SerilogLogger.GetKeyWithoutFirstSymbol(SerilogLogger.StringifyDictionary, key);
+            value = value?.ToString();
+        }
+
+        var property = propertyFactory.CreateProperty(key, value, destructureObject);
+        logEvent.AddPropertyIfAbsent(property);
+    }
 }

src/Serilog.Extensions.Logging/Serilog.Extensions.Logging.csproj

@@ -20,7 +20,7 @@
   <ItemGroup>
     <None Include="..\..\assets\serilog-extension-nuget.png" Pack="true" PackagePath="" Visible="false" />
     <None Include="..\..\README.md" Pack="true" PackagePath="\" Visible="false" />
-    <PackageReference Include="Serilog" Version="4.2.0-*" />
+    <PackageReference Include="Serilog" Version="4.2.0" />
     <!-- The version of this reference must match the major and minor components of the package version prefix. -->
     <PackageReference Include="Microsoft.Extensions.Logging" Version="9.0.0" />
     <PackageReference Include="Nullable" Version="1.3.1" PrivateAssets="All" />

test/Serilog.Extensions.Logging.Benchmarks/LogEventConstructionBenchmark.cs renamed to test/Serilog.Extensions.Logging.Benchmarks/EventIdCapturingBenchmark.cs

@@ -23,19 +23,19 @@
 namespace Serilog.Extensions.Logging.Benchmarks;
 
 [MemoryDiagnoser]
-public class LogEventConstructionBenchmark
+public class EventIdCapturingBenchmark
 {
     readonly IMelLogger _melLogger;
     readonly ILogger _serilogContextualLogger;
     readonly CapturingSink _sink;
     const int LowId = 10, HighId = 101;
     const string Template = "This is an event";
 
-    public LogEventConstructionBenchmark()
+    public EventIdCapturingBenchmark()
     {
         _sink = new CapturingSink();
         var underlyingLogger = new LoggerConfiguration().WriteTo.Sink(_sink).CreateLogger();
-        _serilogContextualLogger = underlyingLogger.ForContext<LogEventConstructionBenchmark>();
+        _serilogContextualLogger = underlyingLogger.ForContext<EventIdCapturingBenchmark>();
         _melLogger = new SerilogLoggerProvider(underlyingLogger).CreateLogger(GetType().FullName!);
     }
 
@@ -68,7 +68,7 @@ public void Verify()
     [Fact]
     public void Benchmark()
     {
-        BenchmarkRunner.Run<LogEventConstructionBenchmark>();
+        BenchmarkRunner.Run<EventIdCapturingBenchmark>();
     }
 
     [Benchmark(Baseline = true)]