Skip to content
Merged
Show file tree
Hide file tree
Changes from 9 commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions serilog-extensions-logging.sln.DotSettings
Original file line number Diff line number Diff line change
@@ -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>
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,8 @@ public static LogEventLevel ToSerilogLevel(LogLevel logLevel)
{
return logLevel switch
{
LogLevel.None or LogLevel.Critical => LogEventLevel.Fatal,
LogLevel.None => LevelAlias.Off,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

bugfix?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think it'll have any effect in the way it's used, here, since events should never carry None - just makes the code clearer.

LogLevel.Critical => LogEventLevel.Fatal,
LogLevel.Error => LogEventLevel.Error,
LogLevel.Warning => LogEventLevel.Warning,
LogLevel.Information => LogEventLevel.Information,
Expand Down
34 changes: 19 additions & 15 deletions src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs
Original file line number Diff line number Diff line change
Expand Up @@ -93,30 +93,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("@"))
else if (property.Key.StartsWith("@", StringComparison.Ordinal))
{
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("$"))
else if (property.Key.StartsWith("$", StringComparison.Ordinal))
{
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))
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would prefer to use ScalarValue.Null for property.Value is null check.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍 will take a look

properties[property.Key] = new ScalarValue(property.Value);
else if (_logger.BindProperty(property.Key, property.Value, false, out var bound))
properties[bound.Name] = bound.Value;
}
}

Expand All @@ -127,7 +130,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;
}
}

Expand All @@ -150,19 +153,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(CreateEventIdProperty(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 ?? "");
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)
Expand All @@ -173,7 +177,7 @@ LogEvent PrepareWrite<TState>(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<LogEventProperty>(2);

Expand All @@ -191,6 +195,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);
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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;

/// <summary>
/// Construct a <see cref="SerilogLoggerProvider"/>.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -49,68 +49,64 @@ 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;
return;
}

// 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);
}
}
}
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);
}
else
{
scopeItem = propertyFactory.CreateProperty(NoName, _state).Value;
}
}

static void AddProperty(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, string key, object? value)
{
var destructureObject = false;

if (key.StartsWith("@", StringComparison.Ordinal))
{
key = SerilogLogger.GetKeyWithoutFirstSymbol(SerilogLogger.DestructureDictionary, key);
destructureObject = true;
}
else if (key.StartsWith("$", StringComparison.Ordinal))
{
key = SerilogLogger.GetKeyWithoutFirstSymbol(SerilogLogger.StringifyDictionary, key);
value = value?.ToString();
}

var property = propertyFactory.CreateProperty(key, value, destructureObject);
logEvent.AddPropertyIfAbsent(property);
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -29,7 +29,7 @@
<None Include="..\..\assets\serilog-extension-nuget.png" Pack="true" PackagePath="" Visible="false" />
<None Include="..\..\README.md" Pack="true" PackagePath="\" Visible="false" />
<PackageReference Include="Microsoft.SourceLink.GitHub" Version="1.1.1" PrivateAssets="All" />
<PackageReference Include="Serilog" Version="3.1.1" />
<PackageReference Include="Serilog" Version="4.0.0-*" />
<!-- The version of this reference must match the major and minor components of the package version prefix. -->
<PackageReference Include="Microsoft.Extensions.Logging" Version="8.0.0" />
<PackageReference Include="Nullable" Version="1.3.1" PrivateAssets="All" />
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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!);
}

Expand Down Expand Up @@ -68,7 +68,7 @@ public void Verify()
[Fact]
public void Benchmark()
{
BenchmarkRunner.Run<LogEventConstructionBenchmark>();
BenchmarkRunner.Run<EventIdCapturingBenchmark>();
}

[Benchmark(Baseline = true)]
Expand Down
125 changes: 86 additions & 39 deletions test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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<LogEventBenchmark>();
}

[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<string, object> { ["Property1"] = 42 });
_melLogger.LogInformation("Hello!");
}

[Benchmark]
public void Capturing()
{
_melLogger.LogInformation("Hi {@User} from {$Me}", _bob, _alice);
}

[Benchmark]
public void CapturingScope()
{
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;

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<LogEventBenchmark>();
}

[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");
}
}
Loading