Merge pull request #260 from AndreReise/improve-event-id-cache

Size-based `EventId` `LogEventProperty` cache

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

@@ -0,0 +1,97 @@
+// Copyright (c) Serilog Contributors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+namespace Serilog.Extensions.Logging;
+
+using System.Collections.Concurrent;
+using Microsoft.Extensions.Logging;
+using Serilog.Events;
+
+class EventIdPropertyCache
+{
+    readonly int _maxCachedProperties;
+    readonly ConcurrentDictionary<EventKey, LogEventProperty> _propertyCache = new();
+
+    int _count;
+
+    public EventIdPropertyCache(int maxCachedProperties = 1024)
+    {
+        _maxCachedProperties = maxCachedProperties;
+    }
+
+    public LogEventProperty GetOrCreateProperty(in EventId eventId)
+    {
+        var eventKey = new EventKey(eventId);
+
+        LogEventProperty? property;
+
+        if (_count >= _maxCachedProperties)
+        {
+            if (!_propertyCache.TryGetValue(eventKey, out property))
+            {
+                property = CreateProperty(in eventKey);
+            }
+        }
+        else
+        {
+            if (!_propertyCache.TryGetValue(eventKey, out property))
+            {
+                // GetOrAdd is moved to a separate method to prevent closure allocation
+                property = GetOrAddCore(in eventKey);
+            }
+        }
+
+        return property;
+    }
+
+    static LogEventProperty CreateProperty(in EventKey eventKey)
+    {
+        var properties = new List<LogEventProperty>(2);
+
+        if (eventKey.Id != 0)
+        {
+            properties.Add(new LogEventProperty("Id", new ScalarValue(eventKey.Id)));
+        }
+
+        if (eventKey.Name != null)
+        {
+            properties.Add(new LogEventProperty("Name", new ScalarValue(eventKey.Name)));
+        }
+
+        return new LogEventProperty("EventId", new StructureValue(properties));
+    }
+
+    LogEventProperty GetOrAddCore(in EventKey eventKey) =>
+        _propertyCache.GetOrAdd(
+            eventKey,
+            key =>
+            {
+                Interlocked.Increment(ref _count);
+
+                return CreateProperty(in key);
+            });
+
+    readonly record struct EventKey
+    {
+        public EventKey(EventId eventId)
+        {
+            Id = eventId.Id;
+            Name = eventId.Name;
+        }
+
+        public int Id { get; }
+
+        public string? Name { get; }
+    }
+}

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

@@ -28,14 +28,10 @@ internal static string GetKeyWithoutFirstSymbol(ConcurrentDictionary<string, str
 
     readonly SerilogLoggerProvider _provider;
     readonly ILogger _logger;
+    readonly EventIdPropertyCache _eventIdPropertyCache = new();
 
     static readonly CachingMessageTemplateParser MessageTemplateParser = new();
 
-    // It's rare to see large event ids, as they are category-specific
-    static readonly LogEventProperty[] LowEventIdValues = Enumerable.Range(0, 48)
-        .Select(n => new LogEventProperty("Id", new ScalarValue(n)))
-        .ToArray();
-
     public SerilogLogger(
         SerilogLoggerProvider provider,
         ILogger? logger = null,
@@ -155,7 +151,7 @@ LogEvent PrepareWrite<TState>(LogEventLevel level, EventId eventId, TState state
         }
 
         if (eventId.Id != 0 || eventId.Name != null)
-            properties.Add(CreateEventIdProperty(eventId));
+            properties.Add(_eventIdPropertyCache.GetOrCreateProperty(in eventId));
 
         var (traceId, spanId) = Activity.Current is { } activity ?
             (activity.TraceId, activity.SpanId) :
@@ -172,25 +168,4 @@ LogEvent PrepareWrite<TState>(LogEventLevel level, EventId eventId, TState state
             stateObj = formatter(state, null);
         return stateObj ?? state;
     }
-
-    internal static LogEventProperty CreateEventIdProperty(EventId eventId)
-    {
-        var properties = new List<LogEventProperty>(2);
-
-        if (eventId.Id != 0)
-        {
-            if (eventId.Id >= 0 && eventId.Id < LowEventIdValues.Length)
-                // Avoid some allocations
-                properties.Add(LowEventIdValues[eventId.Id]);
-            else
-                properties.Add(new LogEventProperty("Id", new ScalarValue(eventId.Id)));
-        }
-
-        if (eventId.Name != null)
-        {
-            properties.Add(new LogEventProperty("Name", new ScalarValue(eventId.Name)));
-        }
-
-        return new LogEventProperty("EventId", new StructureValue(properties));
-    }
 }

test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs

@@ -34,6 +34,7 @@ private class Person
 
         readonly IMelLogger _melLogger;
         readonly Person _bob, _alice;
+        readonly EventId _eventId = new EventId(1, "Test");
 
         public LogEventBenchmark()
         {
@@ -61,5 +62,16 @@ public void LogInformationScoped()
             using (var scope = _melLogger.BeginScope("Hi {@User} from {$Me}", _bob, _alice))
                 _melLogger.LogInformation("Hi");
         }
+
+        [Benchmark]
+        public void LogInformation_WithEventId()
+        {
+            this._melLogger.Log(
+                LogLevel.Information,
+                _eventId,
+                "Hi {@User} from {$Me}",
+                _bob,
+                _alice);
+        }
     }
 }

test/Serilog.Extensions.Logging.Tests/EventIdPropertyCacheTests.cs

@@ -0,0 +1,114 @@
+// Copyright (c) Serilog Contributors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+using Microsoft.Extensions.Logging;
+using Serilog.Events;
+using Xunit;
+
+namespace Serilog.Extensions.Logging.Tests;
+
+public class EventIdPropertyCacheTests
+{
+    [Fact]
+    public void CreatesPropertyWithCorrectIdAndName()
+    {
+        // Arrange
+        const int id = 101;
+        const string name = "TestEvent";
+        var eventId = new EventId(id, name);
+
+        var cache = new EventIdPropertyCache();
+
+        // Act
+        var eventProperty = cache.GetOrCreateProperty(eventId);
+
+        // Assert
+        var value = Assert.IsType<StructureValue>(eventProperty.Value);
+
+        Assert.Equal(2, value.Properties.Count);
+
+        var idValue = value.Properties.Single(property => property.Name == "Id").Value;
+        var nameValue = value.Properties.Single(property => property.Name == "Name").Value;
+
+        var scalarId = Assert.IsType<ScalarValue>(idValue);
+        var scalarName = Assert.IsType<ScalarValue>(nameValue);
+
+        Assert.Equal(id, scalarId.Value);
+        Assert.Equal(name, scalarName.Value);
+    }
+
+    [Fact]
+    public void EventsWithDSameKeysHaveSameReferences()
+    {
+        // Arrange
+        var cache = new EventIdPropertyCache();
+
+        // Act
+        var property1 = cache.GetOrCreateProperty(new EventId(1, "Name1"));
+        var property2 = cache.GetOrCreateProperty(new EventId(1, "Name1"));
+
+        // Assert
+        Assert.Same(property1, property2);
+    }
+
+    [Theory]
+    [InlineData(1, "SomeName", 1, "AnotherName")]
+    [InlineData(1, "SomeName", 2, "SomeName")]
+    [InlineData(1, "SomeName", 2, "AnotherName")]
+    public void EventsWithDifferentKeysHaveDifferentReferences(int firstId, string firstName, int secondId, string secondName)
+    {
+        // Arrange
+        var cache = new EventIdPropertyCache();
+
+        // Act
+        var property1 = cache.GetOrCreateProperty(new EventId(firstId, firstName));
+        var property2 = cache.GetOrCreateProperty(new EventId(secondId, secondName));
+
+        // Assert
+        Assert.NotSame(property1, property2);
+    }
+
+
+    [Fact]
+    public void WhenLimitIsNotOverSameEventsHaveSameReferences()
+    {
+        // Arrange
+        var eventId = new EventId(101, "test");
+        var cache = new EventIdPropertyCache();
+
+        // Act
+        var property1 = cache.GetOrCreateProperty(eventId);
+        var property2 = cache.GetOrCreateProperty(eventId);
+
+        // Assert
+        Assert.Same(property1, property2);
+    }
+
+    [Fact]
+    public void WhenLimitIsOverSameEventsHaveDifferentReferences()
+    {
+        // Arrange
+        var cache = new EventIdPropertyCache(maxCachedProperties: 1);
+        cache.GetOrCreateProperty(new EventId(1, "InitialEvent"));
+
+        var eventId = new EventId(101, "DifferentEvent");
+
+        // Act
+        var property1 = cache.GetOrCreateProperty(eventId);
+        var property2 = cache.GetOrCreateProperty(eventId);
+
+        // Assert
+        Assert.NotSame(property1, property2);
+    }
+}

test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs

@@ -517,22 +517,6 @@ public void Dispose()
         }
     }
 
-    [Theory]
-    [InlineData(1)]
-    [InlineData(10)]
-    [InlineData(48)]
-    [InlineData(100)]
-    public void LowAndHighNumberedEventIdsAreMapped(int id)
-    {
-        var orig = new EventId(id, "test");
-        var mapped = SerilogLogger.CreateEventIdProperty(orig);
-        var value = Assert.IsType<StructureValue>(mapped.Value);
-        Assert.Equal(2, value.Properties.Count);
-        var idValue = value.Properties.Single(p => p.Name == "Id").Value;
-        var scalar = Assert.IsType<ScalarValue>(idValue);
-        Assert.Equal(id, scalar.Value);
-    }
-
     [Fact]
     public void MismatchedMessageTemplateParameterCountIsHandled()
     {