Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Update to Serilog 4.x, remove some allocations #247

Merged
merged 12 commits into from
Dec 6, 2024
Merged
Show file tree
Hide file tree
Changes from all 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 @@ -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;

Expand All @@ -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);

Expand All @@ -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
Expand Down
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
26 changes: 15 additions & 11 deletions src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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))
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 @@ -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;
}
}

Expand All @@ -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)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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);
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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" />
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
Loading