From 62b775b48084b6ff1227617665b898e4cf7ee0ce Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Fri, 15 Mar 2024 11:04:16 +1000 Subject: [PATCH 1/9] Move AddProperty() out to avoid a closure allocation --- serilog-extensions-logging.sln.DotSettings | 1 + .../Logging/SerilogLoggerProvider.cs | 2 +- .../Extensions/Logging/SerilogLoggerScope.cs | 44 +++++++++---------- 3 files changed, 24 insertions(+), 23 deletions(-) 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/SerilogLoggerProvider.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerProvider.cs index 5a603bc..115a8b0 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerProvider.cs +++ b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerProvider.cs @@ -21,7 +21,7 @@ public class SerilogLoggerProvider : ILoggerProvider, ILogEventEnricher, ISuppor // May be null; if it is, Log.Logger will be lazily used readonly ILogger? _logger; readonly Action? _dispose; - private IExternalScopeProvider? _externalScopeProvider; + IExternalScopeProvider? _externalScopeProvider; /// /// Construct a . diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs index 4d4a2c1..25d2ae7 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs +++ b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs @@ -49,25 +49,6 @@ public void Dispose() public void EnrichAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, 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; @@ -84,7 +65,7 @@ void AddProperty(string key, object? value) 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) @@ -96,7 +77,7 @@ void AddProperty(string key, object? value) 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 ValueTuple tuple) @@ -106,11 +87,30 @@ void AddProperty(string key, object? value) if (tuple.Item1 == SerilogLoggerProvider.OriginalFormatPropertyName && tuple.Item2 is string) scopeItem = new ScalarValue(_state.ToString()); else - AddProperty(tuple.Item1, tuple.Item2); + AddProperty(logEvent, propertyFactory, tuple.Item1, tuple.Item2); } 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); + } } From f8452370e5779fe7a6de115eb3497bf254015d3e Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Fri, 15 Mar 2024 11:08:51 +1000 Subject: [PATCH 2/9] It's not necessary to handle {OriginalFormat} when TState is Dictionary or (K,V). --- .../Extensions/Logging/SerilogLoggerScope.cs | 28 ++++++++----------- 1 file changed, 12 insertions(+), 16 deletions(-) diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs index 25d2ae7..af76248 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs +++ b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs @@ -55,39 +55,35 @@ public void EnrichAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory return; } - // 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(logEvent, propertyFactory, 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(logEvent, propertyFactory, stateProperty.Key, stateProperty.Value); + } } } 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(logEvent, propertyFactory, tuple.Item1, tuple.Item2); + scopeItem = null; + AddProperty(logEvent, propertyFactory, tuple.Item1, tuple.Item2); } else { From 5864a5db432fc0c314499bf9151a0045526e844a Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Fri, 15 Mar 2024 11:16:15 +1000 Subject: [PATCH 3/9] Use LogEvent.UnstableAssembleFromParts() to avoid a dictionary alloc --- .../Extensions/Logging/SerilogLogger.cs | 22 +++++++++---------- .../Serilog.Extensions.Logging.csproj | 2 +- .../LogEventBenchmark.cs | 6 ++--- .../SerilogLoggerTests.cs | 7 +++--- 4 files changed, 18 insertions(+), 19 deletions(-) diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs index 9a82609..45399bc 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs +++ b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs @@ -93,30 +93,30 @@ 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.Add(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.Add(stringified.Name, stringified.Value); } else { if (_logger.BindProperty(property.Key, property.Value, false, out var bound)) - properties.Add(bound); + properties.Add(bound.Name, bound.Value); } } @@ -127,7 +127,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.Add(stateTypeProperty.Name, stateTypeProperty.Value); } } @@ -150,19 +150,19 @@ 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.Add(property.Name, property.Value); } } if (eventId.Id != 0 || eventId.Name != null) - properties.Add(CreateEventIdProperty(eventId)); + properties.Add("EventId", CreateEventIdPropertyValue(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); + return LogEvent.UnstableAssembleFromParts(DateTimeOffset.Now, level, exception, parsedTemplate, properties, traceId, spanId); } static object? AsLoggableValue(TState state, Func? formatter) @@ -173,7 +173,7 @@ LogEvent PrepareWrite(LogEventLevel level, EventId eventId, TState state return stateObj ?? state; } - internal static LogEventProperty CreateEventIdProperty(EventId eventId) + internal static StructureValue CreateEventIdPropertyValue(EventId eventId) { var properties = new List(2); @@ -191,6 +191,6 @@ internal static LogEventProperty CreateEventIdProperty(EventId eventId) properties.Add(new LogEventProperty("Name", new ScalarValue(eventId.Name))); } - return new LogEventProperty("EventId", new StructureValue(properties)); + return new StructureValue(properties); } } diff --git a/src/Serilog.Extensions.Logging/Serilog.Extensions.Logging.csproj b/src/Serilog.Extensions.Logging/Serilog.Extensions.Logging.csproj index a197a45..f63b130 100644 --- a/src/Serilog.Extensions.Logging/Serilog.Extensions.Logging.csproj +++ b/src/Serilog.Extensions.Logging/Serilog.Extensions.Logging.csproj @@ -29,7 +29,7 @@ - + diff --git a/test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs b/test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs index 995d462..4c37ae6 100644 --- a/test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs +++ b/test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs @@ -25,7 +25,7 @@ namespace Serilog.Extensions.Logging.Benchmarks [MemoryDiagnoser] public class LogEventBenchmark { - private class Person + class Person { public string? Name { get; set; } public int Age { get; set; } @@ -58,8 +58,8 @@ public void LogInformation() [Benchmark] public void LogInformationScoped() { - using (var scope = _melLogger.BeginScope("Hi {@User} from {$Me}", _bob, _alice)) - _melLogger.LogInformation("Hi"); + using var scope = _melLogger.BeginScope("Hi {@User} from {$Me}", _bob, _alice); + _melLogger.LogInformation("Hi"); } } } diff --git a/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs b/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs index 84bba82..296eb62 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) @@ -525,8 +525,7 @@ public void Dispose() public void LowAndHighNumberedEventIdsAreMapped(int id) { var orig = new EventId(id, "test"); - var mapped = SerilogLogger.CreateEventIdProperty(orig); - var value = Assert.IsType(mapped.Value); + var value = SerilogLogger.CreateEventIdPropertyValue(orig); Assert.Equal(2, value.Properties.Count); var idValue = value.Properties.Single(p => p.Name == "Id").Value; var scalar = Assert.IsType(idValue); From 1c77935b512918d95abbe90b695e2c2d9bf4352d Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Fri, 15 Mar 2024 12:16:08 +1000 Subject: [PATCH 4/9] Update BenchmarkDotNet --- .../Serilog.Extensions.Logging.Benchmarks.csproj | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/Serilog.Extensions.Logging.Benchmarks/Serilog.Extensions.Logging.Benchmarks.csproj b/test/Serilog.Extensions.Logging.Benchmarks/Serilog.Extensions.Logging.Benchmarks.csproj index 155847e..56b4b50 100644 --- a/test/Serilog.Extensions.Logging.Benchmarks/Serilog.Extensions.Logging.Benchmarks.csproj +++ b/test/Serilog.Extensions.Logging.Benchmarks/Serilog.Extensions.Logging.Benchmarks.csproj @@ -13,7 +13,7 @@ - + From 03fcf95497eb38242980b43c6de3d879be3fee9d Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Fri, 15 Mar 2024 13:04:47 +1000 Subject: [PATCH 5/9] "Improve LogEventBenchmark benchmarks": --- .../Extensions/Logging/SerilogLogger.cs | 7 +- .../LogEventBenchmark.cs | 125 ++++++++++++------ 2 files changed, 91 insertions(+), 41 deletions(-) diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs index 45399bc..23b3f1a 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs +++ b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs @@ -115,7 +115,10 @@ LogEvent PrepareWrite(LogEventLevel level, EventId eventId, TState state } else { - if (_logger.BindProperty(property.Key, property.Value, false, out var 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.Add(property.Key, new ScalarValue(property.Value)); + else if (_logger.BindProperty(property.Key, property.Value, false, out var bound)) properties.Add(bound.Name, bound.Value); } } @@ -154,7 +157,7 @@ LogEvent PrepareWrite(LogEventLevel level, EventId eventId, TState state } } - if (eventId.Id != 0 || eventId.Name != null) + if (eventId != default) properties.Add("EventId", CreateEventIdPropertyValue(eventId)); var (traceId, spanId) = Activity.Current is { } activity ? diff --git a/test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs b/test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs index 4c37ae6..461e918 100644 --- a/test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs +++ b/test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs @@ -20,46 +20,93 @@ #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; + + 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() { - 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; - - 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"); - } + using var scope = _melLogger.BeginScope("Hi {@User} from {$Me}", _bob, _alice); + _melLogger.LogInformation("Hi"); } } From bcc50219b6eed28acf53a1cd1fa26e441199c67d Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Mon, 18 Mar 2024 10:08:16 +1000 Subject: [PATCH 6/9] Ordinal string comparisons --- .../Extensions/Logging/SerilogLogger.cs | 4 ++-- .../Extensions/Logging/SerilogLoggerScope.cs | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs index 23b3f1a..2937b14 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs +++ b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs @@ -103,12 +103,12 @@ LogEvent PrepareWrite(LogEventLevel level, EventId eventId, TState state { messageTemplate = value; } - else if (property.Key.StartsWith("@")) + else if (property.Key.StartsWith("@", StringComparison.Ordinal)) { if (_logger.BindProperty(GetKeyWithoutFirstSymbol(DestructureDictionary, property.Key), property.Value, true, out var destructured)) properties.Add(destructured.Name, destructured.Value); } - else if (property.Key.StartsWith("$")) + else if (property.Key.StartsWith("$", StringComparison.Ordinal)) { if (_logger.BindProperty(GetKeyWithoutFirstSymbol(StringifyDictionary, property.Key), property.Value?.ToString(), true, out var stringified)) properties.Add(stringified.Name, stringified.Value); diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs index af76248..4e14446 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs +++ b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs @@ -95,12 +95,12 @@ static void AddProperty(LogEvent logEvent, ILogEventPropertyFactory propertyFact { var destructureObject = false; - if (key.StartsWith("@")) + if (key.StartsWith("@", StringComparison.Ordinal)) { key = SerilogLogger.GetKeyWithoutFirstSymbol(SerilogLogger.DestructureDictionary, key); destructureObject = true; } - else if (key.StartsWith("$")) + else if (key.StartsWith("$", StringComparison.Ordinal)) { key = SerilogLogger.GetKeyWithoutFirstSymbol(SerilogLogger.StringifyDictionary, key); value = value?.ToString(); From ccae6ff98f15a88fe1c4b7804c79c997e8b258d5 Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Mon, 18 Mar 2024 10:12:24 +1000 Subject: [PATCH 7/9] Remove some accidental usages of throwing Dictionary<,>.Add() --- .../Extensions/Logging/SerilogLogger.cs | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs index 2937b14..218fa5e 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs +++ b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs @@ -106,20 +106,20 @@ LogEvent PrepareWrite(LogEventLevel level, EventId eventId, TState state else if (property.Key.StartsWith("@", StringComparison.Ordinal)) { if (_logger.BindProperty(GetKeyWithoutFirstSymbol(DestructureDictionary, property.Key), property.Value, true, out var destructured)) - properties.Add(destructured.Name, destructured.Value); + properties[destructured.Name] = destructured.Value; } else if (property.Key.StartsWith("$", StringComparison.Ordinal)) { if (_logger.BindProperty(GetKeyWithoutFirstSymbol(StringifyDictionary, property.Key), property.Value?.ToString(), true, out var stringified)) - properties.Add(stringified.Name, stringified.Value); + properties[stringified.Name] = stringified.Value; } else { // 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.Add(property.Key, new ScalarValue(property.Value)); + properties[property.Key] = new ScalarValue(property.Value); else if (_logger.BindProperty(property.Key, property.Value, false, out var bound)) - properties.Add(bound.Name, bound.Value); + properties[bound.Name] = bound.Value; } } @@ -130,7 +130,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.Name, stateTypeProperty.Value); + properties[stateTypeProperty.Name] = stateTypeProperty.Value; } } @@ -153,18 +153,18 @@ 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.Name, property.Value); + properties[property.Name] = property.Value; } } if (eventId != default) - properties.Add("EventId", CreateEventIdPropertyValue(eventId)); + properties["EventId"] = CreateEventIdPropertyValue(eventId); var (traceId, spanId) = Activity.Current is { } activity ? (activity.TraceId, activity.SpanId) : (default(ActivityTraceId), default(ActivitySpanId)); - var parsedTemplate = MessageTemplateParser.Parse(messageTemplate ?? ""); + var parsedTemplate = messageTemplate != null ? MessageTemplateParser.Parse(messageTemplate) : MessageTemplate.Empty; return LogEvent.UnstableAssembleFromParts(DateTimeOffset.Now, level, exception, parsedTemplate, properties, traceId, spanId); } From 7bdddecdee0622268a3e390ec363d10c95425ddc Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Mon, 18 Mar 2024 10:15:48 +1000 Subject: [PATCH 8/9] Roll back EventId comparison change; the overridden != operator does not compare names --- .../Extensions/Logging/SerilogLogger.cs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs index 218fa5e..3734e52 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs +++ b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs @@ -157,7 +157,8 @@ LogEvent PrepareWrite(LogEventLevel level, EventId eventId, TState state } } - if (eventId != default) + // The overridden `!=` operator on this type ignores `Name`. + if (eventId.Id != 0 || eventId.Name != null) properties["EventId"] = CreateEventIdPropertyValue(eventId); var (traceId, spanId) = Activity.Current is { } activity ? From adf275fa7b11c339a2b5cfb62c9934052f6b123c Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Mon, 18 Mar 2024 11:05:39 +1000 Subject: [PATCH 9/9] Tighter level mapping, though for invalid cases only --- .../Extensions/Logging/LevelConvert.cs | 3 ++- ...structionBenchmark.cs => EventIdCapturingBenchmark.cs} | 8 ++++---- 2 files changed, 6 insertions(+), 5 deletions(-) rename test/Serilog.Extensions.Logging.Benchmarks/{LogEventConstructionBenchmark.cs => EventIdCapturingBenchmark.cs} (92%) 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/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)]