diff --git a/serilog-extensions-logging.sln.DotSettings b/serilog-extensions-logging.sln.DotSettings index 23a0f99..6fd2e62 100644 --- a/serilog-extensions-logging.sln.DotSettings +++ b/serilog-extensions-logging.sln.DotSettings @@ -1,2 +1,3 @@  + True True \ No newline at end of file diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/EventIdPropertyCache.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/EventIdPropertyCache.cs index f7ce438..60d7efe 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/EventIdPropertyCache.cs +++ b/src/Serilog.Extensions.Logging/Extensions/Logging/EventIdPropertyCache.cs @@ -21,7 +21,7 @@ namespace Serilog.Extensions.Logging; sealed class EventIdPropertyCache { readonly int _maxCachedProperties; - readonly ConcurrentDictionary _propertyCache = new(); + readonly ConcurrentDictionary _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(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 diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/LevelConvert.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/LevelConvert.cs index a77494e..cce77da 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/LevelConvert.cs +++ b/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, diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs index 05f6bdd..cae926c 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs +++ b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs @@ -89,30 +89,33 @@ LogEvent PrepareWrite(LogEventLevel level, EventId eventId, TState state { string? messageTemplate = null; - var properties = new List(); + var properties = new Dictionary(); if (state is IEnumerable> 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(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(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 state, Func? formatter) diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs index 8e71133..b03e3e1 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs +++ b/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,47 +60,40 @@ void AddProperty(string key, object? value) // Eliminates boxing of Dictionary.Enumerator for the most common use case if (state is Dictionary 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.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> 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 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 @@ -127,4 +101,23 @@ void AddProperty(string key, object? value) 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); + } } diff --git a/src/Serilog.Extensions.Logging/Serilog.Extensions.Logging.csproj b/src/Serilog.Extensions.Logging/Serilog.Extensions.Logging.csproj index e1a3a12..3030973 100644 --- a/src/Serilog.Extensions.Logging/Serilog.Extensions.Logging.csproj +++ b/src/Serilog.Extensions.Logging/Serilog.Extensions.Logging.csproj @@ -20,7 +20,7 @@ - + diff --git a/test/Serilog.Extensions.Logging.Benchmarks/LogEventConstructionBenchmark.cs b/test/Serilog.Extensions.Logging.Benchmarks/EventIdCapturingBenchmark.cs similarity index 92% rename from test/Serilog.Extensions.Logging.Benchmarks/LogEventConstructionBenchmark.cs rename to test/Serilog.Extensions.Logging.Benchmarks/EventIdCapturingBenchmark.cs index 415867a..a16f38f 100644 --- a/test/Serilog.Extensions.Logging.Benchmarks/LogEventConstructionBenchmark.cs +++ b/test/Serilog.Extensions.Logging.Benchmarks/EventIdCapturingBenchmark.cs @@ -23,7 +23,7 @@ namespace Serilog.Extensions.Logging.Benchmarks; [MemoryDiagnoser] -public class LogEventConstructionBenchmark +public class EventIdCapturingBenchmark { readonly IMelLogger _melLogger; readonly ILogger _serilogContextualLogger; @@ -31,11 +31,11 @@ public class LogEventConstructionBenchmark 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(); + _serilogContextualLogger = underlyingLogger.ForContext(); _melLogger = new SerilogLoggerProvider(underlyingLogger).CreateLogger(GetType().FullName!); } @@ -68,7 +68,7 @@ public void Verify() [Fact] public void Benchmark() { - BenchmarkRunner.Run(); + BenchmarkRunner.Run(); } [Benchmark(Baseline = true)] diff --git a/test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs b/test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs index 6393348..f08738a 100644 --- a/test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs +++ b/test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs @@ -20,58 +20,112 @@ #pragma warning disable xUnit1013 // Public method should be marked as test -namespace Serilog.Extensions.Logging.Benchmarks +namespace Serilog.Extensions.Logging.Benchmarks; + +[MemoryDiagnoser] +public class LogEventBenchmark { - [MemoryDiagnoser] - public class LogEventBenchmark + class Person + { + public string? Name { get; set; } + public int Age { get; set; } + public override string ToString() => "Fixed text"; + } + + readonly IMelLogger _melLogger; + readonly Person _bob, _alice; + readonly ILogger _underlyingLogger; + readonly EventId _eventId = new EventId(1, "Test"); + + public LogEventBenchmark() + { + _underlyingLogger = new LoggerConfiguration().CreateLogger(); + _melLogger = new SerilogLoggerProvider(_underlyingLogger).CreateLogger(GetType().FullName!); + _bob = new Person { Name = "Bob", Age = 42 }; + _alice = new Person { Name = "Alice", Age = 42 }; + } + + [Fact] + public void Benchmark() + { + BenchmarkRunner.Run(); + } + + [Benchmark(Baseline = true)] + public void SerilogOnly() + { + _underlyingLogger.Information("Hello!"); + } + + [Benchmark] + public void SimpleEvent() + { + _melLogger.LogInformation("Hello!"); + } + + [Benchmark] + public void Template() + { + _melLogger.LogInformation("Hello, {Property1}!", 42); + } + + [Benchmark] + public void StringScope() + { + using var scope = _melLogger.BeginScope("Scope1"); + _melLogger.LogInformation("Hello!"); + } + + [Benchmark] + public void TemplateScope() + { + using var scope = _melLogger.BeginScope("Scope1 {Property1}", 42); + _melLogger.LogInformation("Hello!"); + } + + [Benchmark] + public void TupleScope() + { + using var scope = _melLogger.BeginScope(("Property1", 42)); + _melLogger.LogInformation("Hello!"); + } + + [Benchmark] + public void DictionaryScope() + { + // Note that allocations here include the dictionary and boxed int. + using var scope = _melLogger.BeginScope(new Dictionary { ["Property1"] = 42 }); + _melLogger.LogInformation("Hello!"); + } + + [Benchmark] + public void Capturing() + { + _melLogger.LogInformation("Hi {@User} from {$Me}", _bob, _alice); + } + + [Benchmark] + public void CapturingScope() + { + using var scope = _melLogger.BeginScope("Hi {@User} from {$Me}", _bob, _alice); + _melLogger.LogInformation("Hi"); + } + + [Benchmark] + public void LogInformationScoped() + { + using (var scope = _melLogger.BeginScope("Hi {@User} from {$Me}", _bob, _alice)) + _melLogger.LogInformation("Hi"); + } + + [Benchmark] + public void LogInformation_WithEventId() { - private class Person - { - public string? Name { get; set; } - public int Age { get; set; } - public override string ToString() => "Fixed text"; - } - - readonly IMelLogger _melLogger; - readonly Person _bob, _alice; - readonly EventId _eventId = new EventId(1, "Test"); - - public LogEventBenchmark() - { - var underlyingLogger = new LoggerConfiguration().CreateLogger(); - _melLogger = new SerilogLoggerProvider(underlyingLogger).CreateLogger(GetType().FullName!); - _bob = new Person { Name = "Bob", Age = 42 }; - _alice = new Person { Name = "Alice", Age = 42 }; - } - - [Fact] - public void Benchmark() - { - BenchmarkRunner.Run(); - } - - [Benchmark] - public void LogInformation() - { - _melLogger.LogInformation("Hi {@User} from {$Me}", _bob, _alice); - } - - [Benchmark] - 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); - } + this._melLogger.Log( + LogLevel.Information, + _eventId, + "Hi {@User} from {$Me}", + _bob, + _alice); } } diff --git a/test/Serilog.Extensions.Logging.Tests/EventIdPropertyCacheTests.cs b/test/Serilog.Extensions.Logging.Tests/EventIdPropertyCacheTests.cs index 9949cbf..3cb7bd1 100644 --- a/test/Serilog.Extensions.Logging.Tests/EventIdPropertyCacheTests.cs +++ b/test/Serilog.Extensions.Logging.Tests/EventIdPropertyCacheTests.cs @@ -21,7 +21,7 @@ namespace Serilog.Extensions.Logging.Tests; public class EventIdPropertyCacheTests { [Fact] - public void CreatesPropertyWithCorrectIdAndName() + public void CreatesPropertyValueWithCorrectIdAndName() { // Arrange const int id = 101; @@ -31,10 +31,10 @@ public void CreatesPropertyWithCorrectIdAndName() var cache = new EventIdPropertyCache(); // Act - var eventProperty = cache.GetOrCreateProperty(eventId); + var eventPropertyValue = cache.GetOrCreatePropertyValue(eventId); // Assert - var value = Assert.IsType(eventProperty.Value); + var value = Assert.IsType(eventPropertyValue); Assert.Equal(2, value.Properties.Count); @@ -55,11 +55,11 @@ public void EventsWithDSameKeysHaveSameReferences() var cache = new EventIdPropertyCache(); // Act - var property1 = cache.GetOrCreateProperty(new EventId(1, "Name1")); - var property2 = cache.GetOrCreateProperty(new EventId(1, "Name1")); + var propertyValue1 = cache.GetOrCreatePropertyValue(new EventId(1, "Name1")); + var propertyValue2 = cache.GetOrCreatePropertyValue(new EventId(1, "Name1")); // Assert - Assert.Same(property1, property2); + Assert.Same(propertyValue1, propertyValue2); } [Theory] @@ -72,11 +72,11 @@ public void EventsWithDifferentKeysHaveDifferentReferences(int firstId, string f var cache = new EventIdPropertyCache(); // Act - var property1 = cache.GetOrCreateProperty(new EventId(firstId, firstName)); - var property2 = cache.GetOrCreateProperty(new EventId(secondId, secondName)); + var propertyValue1 = cache.GetOrCreatePropertyValue(new EventId(firstId, firstName)); + var propertyValue2 = cache.GetOrCreatePropertyValue(new EventId(secondId, secondName)); // Assert - Assert.NotSame(property1, property2); + Assert.NotSame(propertyValue1, propertyValue2); } @@ -88,11 +88,11 @@ public void WhenLimitIsNotOverSameEventsHaveSameReferences() var cache = new EventIdPropertyCache(); // Act - var property1 = cache.GetOrCreateProperty(eventId); - var property2 = cache.GetOrCreateProperty(eventId); + var propertyValue1 = cache.GetOrCreatePropertyValue(eventId); + var propertyValue2 = cache.GetOrCreatePropertyValue(eventId); // Assert - Assert.Same(property1, property2); + Assert.Same(propertyValue1, propertyValue2); } [Fact] @@ -100,15 +100,15 @@ public void WhenLimitIsOverSameEventsHaveDifferentReferences() { // Arrange var cache = new EventIdPropertyCache(maxCachedProperties: 1); - cache.GetOrCreateProperty(new EventId(1, "InitialEvent")); + cache.GetOrCreatePropertyValue(new EventId(1, "InitialEvent")); var eventId = new EventId(101, "DifferentEvent"); // Act - var property1 = cache.GetOrCreateProperty(eventId); - var property2 = cache.GetOrCreateProperty(eventId); + var propertyValue1 = cache.GetOrCreatePropertyValue(eventId); + var propertyValue2 = cache.GetOrCreatePropertyValue(eventId); // Assert - Assert.NotSame(property1, property2); + Assert.NotSame(propertyValue1, propertyValue2); } } diff --git a/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs b/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs index b23f8f9..274d8ed 100644 --- a/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs +++ b/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs @@ -500,9 +500,9 @@ public IDisposable Push(object? state) return scope; } - private class Scope : IDisposable + class Scope : IDisposable { - public bool IsDisposed { get; set; } = false; + public bool IsDisposed { get; set; } public object? Value { get; set; } public Scope(object? value) @@ -516,7 +516,7 @@ public void Dispose() } } } - + [Fact] public void MismatchedMessageTemplateParameterCountIsHandled() {