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.

Sign up for GitHub

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

Jump to bottom

Removed temporary array allocations for properties #1948

Merged
merged 3 commits into from
Oct 3, 2023
Merged

Removed temporary array allocations for properties #1948

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
b0256a3
Removed temporary array allocations for cases with the small number o…
epeshk Aug 21, 2023
809a496
Added test to ensure that null array does not break message template …
epeshk Oct 2, 2023
ee6dd12
Excluded ILogger.Write<T1, ...> methods from method body comparison t…
epeshk Oct 2, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
6 changes: 5 additions & 1 deletion src/Serilog/Capturing/MessageTemplateProcessor.cs
View file
Open in desktop
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
Open in desktop
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)
Copy link
Member

Choose a reason for hiding this comment

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

May be worth including a few quick speculative tests to check that removing the == null test here is safe even when callers without strict null checking enabled call various logger methods, e.g.:

[Fact]
public void NullMessageTemplateParametersDoNotBreakBinding()
{
    var log = new LoggerConfiguration().WriteTo.Sink(new CollectingSink()).CreateLogger();
    log.Information("test", (object?[]?) null);
    log.BindMessageTemplate("test", (object?[]?)null, out _, out _);
}

?

{
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
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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