Skip to content

Commit

Permalink
Removed temporary array allocations for properties (#1948)
Browse files Browse the repository at this point in the history 
* Removed temporary array allocations for cases with the small number of log event properties

* Added test to ensure that null array does not break message template parameters binding

* Excluded ILogger.Write<T1, ...> methods from method body comparison test.
  • Loading branch information
@epeshk
epeshk committed Oct 3, 2023
1 parent 948ea83 commit d6e80e6
Show file tree
Hide file tree
Showing 6 changed files with 168 additions and 6 deletions.
6 changes: 5 additions & 1 deletion src/Serilog/Capturing/MessageTemplateProcessor.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -26,7 +26,11 @@ public MessageTemplateProcessor(PropertyValueConverter propertyValueConverter)
_propertyBinder = new(_propertyValueConverter);
}

public void Process(string messageTemplate, object?[]? messageTemplateParameters, out MessageTemplate parsedTemplate, out EventProperty[] properties)
#if FEATURE_SPAN
public void Process(string messageTemplate, ReadOnlySpan<object?> messageTemplateParameters, out MessageTemplate parsedTemplate, out EventProperty[] properties)
#else
public void Process(string messageTemplate, object?[] messageTemplateParameters, out MessageTemplate parsedTemplate, out EventProperty[] properties)
#endif
{
parsedTemplate = _parser.Parse(messageTemplate);
properties = _propertyBinder.ConstructProperties(parsedTemplate, messageTemplateParameters);
Expand Down
20 changes: 16 additions & 4 deletions src/Serilog/Capturing/PropertyBinder.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -34,9 +34,13 @@ public PropertyBinder(PropertyValueConverter valueConverter)
/// represented in the message template.</param>
/// <returns>A list of properties; if the template is malformed then
/// this will be empty.</returns>
public EventProperty[] ConstructProperties(MessageTemplate messageTemplate, object?[]? messageTemplateParameters)
#if FEATURE_SPAN
public EventProperty[] ConstructProperties(MessageTemplate messageTemplate, ReadOnlySpan<object?> messageTemplateParameters)
#else
public EventProperty[] ConstructProperties(MessageTemplate messageTemplate, object?[] messageTemplateParameters)
#endif
{
if (messageTemplateParameters == null || messageTemplateParameters.Length == 0)
if (messageTemplateParameters.Length == 0)
{
if (messageTemplate.NamedProperties != null || messageTemplate.PositionalProperties != null)
SelfLog.WriteLine("Required properties not provided for: {0}", messageTemplate);
Expand All @@ -47,10 +51,14 @@ public EventProperty[] ConstructProperties(MessageTemplate messageTemplate, obje
if (messageTemplate.PositionalProperties != null)
return ConstructPositionalProperties(messageTemplate, messageTemplateParameters, messageTemplate.PositionalProperties);

return ConstructNamedProperties(messageTemplate, messageTemplateParameters!);
return ConstructNamedProperties(messageTemplate, messageTemplateParameters);
}

#if FEATURE_SPAN
EventProperty[] ConstructPositionalProperties(MessageTemplate template, ReadOnlySpan<object?> messageTemplateParameters, PropertyToken[] positionalProperties)
#else
EventProperty[] ConstructPositionalProperties(MessageTemplate template, object?[] messageTemplateParameters, PropertyToken[] positionalProperties)
#endif
{
var result = new EventProperty[messageTemplateParameters.Length];
foreach (var property in positionalProperties)
Expand Down Expand Up @@ -83,7 +91,11 @@ EventProperty[] ConstructPositionalProperties(MessageTemplate template, object?[
return result;
}

EventProperty[] ConstructNamedProperties(MessageTemplate template, object[] messageTemplateParameters)
#if FEATURE_SPAN
EventProperty[] ConstructNamedProperties(MessageTemplate template, ReadOnlySpan<object?> messageTemplateParameters)
#else
EventProperty[] ConstructNamedProperties(MessageTemplate template, object?[] messageTemplateParameters)
#endif
{
var namedProperties = template.NamedProperties;
if (namedProperties == null)
Expand Down
78 changes: 77 additions & 1 deletion src/Serilog/Core/Logger.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -207,7 +207,14 @@ public void Write<T>(LogEventLevel level, string messageTemplate, T propertyValu
// Avoid the array allocation and any boxing allocations when the level isn't enabled
if (IsEnabled(level))
{
#if FEATURE_SPAN
var inlineArray = new PropertiesInlineArray();
var span = inlineArray.AsSpan(1);
span[0] = propertyValue;
Write(level, messageTemplate, span);
#else
Write(level, messageTemplate, new object?[] { propertyValue });
#endif
}
}

Expand All @@ -224,7 +231,15 @@ public void Write<T>(LogEventLevel level, string messageTemplate, T propertyValu
// Avoid the array allocation and any boxing allocations when the level isn't enabled
if (IsEnabled(level))
{
#if FEATURE_SPAN
var inlineArray = new PropertiesInlineArray();
var span = inlineArray.AsSpan(2);
span[0] = propertyValue0;
span[1] = propertyValue1;
Write(level, messageTemplate, span);
#else
Write(level, messageTemplate, new object?[] { propertyValue0, propertyValue1 });
#endif
}
}

Expand All @@ -242,7 +257,16 @@ public void Write<T>(LogEventLevel level, string messageTemplate, T propertyValu
// Avoid the array allocation and any boxing allocations when the level isn't enabled
if (IsEnabled(level))
{
#if FEATURE_SPAN
var inlineArray = new PropertiesInlineArray();
var span = inlineArray.AsSpan(3);
span[0] = propertyValue0;
span[1] = propertyValue1;
span[2] = propertyValue2;
Write(level, messageTemplate, span);
#else
Write(level, messageTemplate, new object?[] { propertyValue0, propertyValue1, propertyValue2 });
#endif
}
}

Expand All @@ -258,6 +282,13 @@ public void Write(LogEventLevel level, string messageTemplate, params object?[]?
Write(level, (Exception?)null, messageTemplate, propertyValues);
}

#if FEATURE_SPAN
void Write(LogEventLevel level, string messageTemplate, ReadOnlySpan<object?> propertyValues)
{
Write(level, null, messageTemplate, propertyValues);
}
#endif

/// <summary>
/// Determine if events at the specified level, and higher, will be passed through
/// to the log sinks.
Expand Down Expand Up @@ -302,7 +333,14 @@ public void Write<T>(LogEventLevel level, Exception? exception, string messageTe
// Avoid the array allocation and any boxing allocations when the level isn't enabled
if (IsEnabled(level))
{
#if FEATURE_SPAN
var inlineArray = new PropertiesInlineArray();
var span = inlineArray.AsSpan(1);
span[0] = propertyValue;
Write(level, exception, messageTemplate, span);
#else
Write(level, exception, messageTemplate, new object?[] { propertyValue });
#endif
}
}

Expand All @@ -320,7 +358,15 @@ public void Write<T>(LogEventLevel level, Exception? exception, string messageTe
// Avoid the array allocation and any boxing allocations when the level isn't enabled
if (IsEnabled(level))
{
#if FEATURE_SPAN
var inlineArray = new PropertiesInlineArray();
var span = inlineArray.AsSpan(2);
span[0] = propertyValue0;
span[1] = propertyValue1;
Write(level, exception, messageTemplate, span);
#else
Write(level, exception, messageTemplate, new object?[] { propertyValue0, propertyValue1 });
#endif
}
}

Expand All @@ -339,7 +385,16 @@ public void Write<T>(LogEventLevel level, Exception? exception, string messageTe
// Avoid the array allocation and any boxing allocations when the level isn't enabled
if (IsEnabled(level))
{
#if FEATURE_SPAN
var inlineArray = new PropertiesInlineArray();
var span = inlineArray.AsSpan(3);
span[0] = propertyValue0;
span[1] = propertyValue1;
span[2] = propertyValue2;
Write(level, exception, messageTemplate, span);
#else
Write(level, exception, messageTemplate, new object?[] { propertyValue0, propertyValue1, propertyValue2 });
#endif
}
}

Expand All @@ -361,13 +416,34 @@ public void Write(LogEventLevel level, Exception? exception, string messageTempl
propertyValues.GetType() != typeof(object[]))
propertyValues = new object[] { propertyValues };

var logTimestamp = DateTimeOffset.Now;
#if FEATURE_SPAN
var propertiesSpan = propertyValues == null ? Span<object?>.Empty : propertyValues.AsSpan();
_messageTemplateProcessor.Process(messageTemplate, propertiesSpan, out var parsedTemplate, out var boundProperties);
#else
_messageTemplateProcessor.Process(messageTemplate, propertyValues ?? NoPropertyValues, out var parsedTemplate, out var boundProperties);
#endif

var currentActivity = Activity.Current;
var logEvent = new LogEvent(logTimestamp, level, exception, parsedTemplate, boundProperties, currentActivity?.TraceId ?? default, currentActivity?.SpanId ?? default);
Dispatch(logEvent);
}

#if FEATURE_SPAN
[MessageTemplateFormatMethod("messageTemplate")]
void Write(LogEventLevel level, Exception? exception, string messageTemplate, ReadOnlySpan<object?> propertyValues)
{
if (!IsEnabled(level)) return;
if (messageTemplate == null) return;

var logTimestamp = DateTimeOffset.Now;
_messageTemplateProcessor.Process(messageTemplate, propertyValues, out var parsedTemplate, out var boundProperties);

var currentActivity = Activity.Current;
var logEvent = new LogEvent(logTimestamp, level, exception, parsedTemplate, boundProperties, currentActivity?.TraceId ?? default, currentActivity?.SpanId ?? default);
Dispatch(logEvent);
}
#endif

/// <summary>
/// Write an event to the log.
Expand Down Expand Up @@ -1332,7 +1408,7 @@ public void Fatal(Exception? exception, string messageTemplate, params object?[]
return false;
}

_messageTemplateProcessor.Process(messageTemplate, propertyValues, out parsedTemplate, out var boundEventProperties);
_messageTemplateProcessor.Process(messageTemplate, propertyValues ?? NoPropertyValues, out parsedTemplate, out var boundEventProperties);
boundProperties = boundEventProperties.Length == 0 ?
NoProperties :
boundEventProperties.Select(p => new LogEventProperty(p));
Expand Down
27 changes: 27 additions & 0 deletions src/Serilog/Core/PropertiesInlineArray.cs
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,27 @@
#if FEATURE_SPAN
using System.Runtime.InteropServices;

namespace Serilog.Core;

[StructLayout(LayoutKind.Sequential)]
struct PropertiesInlineArray
{
object? Object1;
object? Object2;
object? Object3;

public Span<object?> AsSpan(int count)
{
if (count is < 0 or > 3)
ThrowArgumentOutOfRangeException(nameof(count));

return MemoryMarshal.CreateSpan(ref Object1, count);
}

[DoesNotReturn]
static void ThrowArgumentOutOfRangeException(string param)
{
throw new ArgumentOutOfRangeException(param);
}
}
#endif
14 changes: 14 additions & 0 deletions test/Serilog.Tests/Core/LoggerTests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -303,6 +303,20 @@ public void CurrentActivityIsCapturedAtLogEventCreation()
Assert.Equal(activity.SpanId, single.SpanId);
}

[Fact]
public void NullMessageTemplateParametersDoNotBreakBinding()
{
var log = new LoggerConfiguration().WriteTo.Sink(new CollectingSink()).CreateLogger();

// ReSharper disable RedundantCast
// ReSharper disable StructuredMessageTemplateProblem
log.Information("test", (object?[]?) null);
log.Write(Warning, (Exception?)null, "test", (object?[]?)null);
log.BindMessageTemplate("test", (object?[]?)null, out _, out _);
// ReSharper restore RedundantCast
// ReSharper restore StructuredMessageTemplateProblem
}

#if FEATURE_ASYNCDISPOSABLE

[Fact]
Expand Down
29 changes: 29 additions & 0 deletions test/Serilog.Tests/MethodOverloadConventionTests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,11 +22,40 @@ public class MethodOverloadConventionTests
const string MessageTemplate = "messageTemplate";

#if FEATURE_DEFAULT_INTERFACE

/// <remarks>
/// <para>
/// Some methods are excluded from the method body comparison.
/// </para>
///
/// <para>
/// Logger.Write methods with generic parameters call
/// <see cref="M:Serilog.Core.Logger.Write(Serilog.Events.LogEventLevel,System.Exception,System.String,System.ReadOnlySpan{System.Object})"/>
/// method to avoid params array allocation.
/// </para>
///
/// <para>
/// A similar <see cref="ReadOnlySpan{T}"/> accepting method does not exists in the <see cref="ILogger"/> interface,
/// and introducing it is a breaking change.
/// </para>
/// </remarks>
static MethodInfo[] ExcludedMethods =
#if FEATURE_SPAN
typeof(ILogger).GetMethods()
.Where(mi => mi.Name == nameof(ILogger.Write))
.Where(mi => mi.GetGenericArguments().Length > 0)
.Where(mi => mi.GetGenericArguments().All(x => x.GetGenericParameterConstraints().Length == 0))
.ToArray();
#else
Array.Empty<MethodInfo>();
#endif

public static IEnumerable<object[]> DefaultInterfaceMethods =>
typeof(ILogger).GetMethods()
.Where(mi => mi.GetMethodBody() != null)
.Where(mi => mi.GetCustomAttribute(typeof(CustomDefaultMethodImplementationAttribute)) == null)
.Where(mi => typeof(Logger).GetInterfaceMap(typeof(ILogger)).InterfaceMethods.Contains(mi))
.Where(mi => !ExcludedMethods.Contains(mi))
.Select(mi => new object[] { mi });

[Theory]
Expand Down

0 comments on commit d6e80e6

Please sign in to comment.