Skip to content

Reduce event source logger allocations #870

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

Merged
merged 6 commits into from
Dec 27, 2018
Merged

Reduce event source logger allocations #870

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
1e77f95
Reduce event source logger allocations
pakrym Dec 26, 2018
eef5595
Test
pakrym Dec 26, 2018
69262d2
Perf bench
pakrym Dec 26, 2018
b2a6554
Test itself
pakrym Dec 26, 2018
cdfa3e4
more
pakrym Dec 27, 2018
61723f0
Feedback
pakrym Dec 27, 2018
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
61 changes: 30 additions & 31 deletions src/Logging/Logging.EventSource/src/EventSourceLogger.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -62,21 +62,23 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
logLevel,
_factoryID,
CategoryName,
eventId.ToString(),
eventId.Id,
eventId.Name,
message);
}

// See if they want the message as its component parts.
if (_eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.Message))
{
ExceptionInfo exceptionInfo = GetExceptionInfo(exception);
IEnumerable<KeyValuePair<string, string>> arguments = GetProperties(state);
var exceptionInfo = GetExceptionInfo(exception);
var arguments = GetProperties(state);

_eventSource.Message(
logLevel,
_factoryID,
CategoryName,
eventId.ToString(),
eventId.Id,
eventId.Name,
exceptionInfo,
arguments);
}
Expand All @@ -88,7 +90,7 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
if (exception != null)
{
var exceptionInfo = GetExceptionInfo(exception);
var exceptionInfoData = new KeyValuePair<string, string>[]
var exceptionInfoData = new []
{
new KeyValuePair<string, string>("TypeName", exceptionInfo.TypeName),
new KeyValuePair<string, string>("Message", exceptionInfo.Message),
Expand All @@ -97,12 +99,13 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
};
exceptionJson = ToJson(exceptionInfoData);
}
IEnumerable<KeyValuePair<string, string>> arguments = GetProperties(state);
var arguments = GetProperties(state);
_eventSource.MessageJson(
logLevel,
_factoryID,
CategoryName,
eventId.ToString(),
eventId.Id,
eventId.Name,
exceptionJson,
ToJson(arguments));
}
Expand All @@ -120,16 +123,20 @@ public IDisposable BeginScope<TState>(TState state)
// If JsonMessage is on, use JSON format
if (_eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.JsonMessage))
{
IEnumerable<KeyValuePair<string, string>> arguments = GetProperties(state);
var arguments = GetProperties(state);
_eventSource.ActivityJsonStart(id, _factoryID, CategoryName, ToJson(arguments));
return new ActivityScope(_eventSource, CategoryName, id, _factoryID, true);
}
else

if (_eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.Message) ||
_eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.FormattedMessage))
{
IEnumerable<KeyValuePair<string, string>> arguments = GetProperties(state);
var arguments = GetProperties(state);
_eventSource.ActivityStart(id, _factoryID, CategoryName, arguments);
return new ActivityScope(_eventSource, CategoryName, id, _factoryID, false);
}

return NullScope.Instance;
}

/// <summary>
Expand Down Expand Up @@ -174,46 +181,38 @@ public void Dispose()
/// <remarks>ETW does not support a concept of a null value. So we use an un-initialized object if there is no exception in the event data.</remarks>
private ExceptionInfo GetExceptionInfo(Exception exception)
{
var exceptionInfo = new ExceptionInfo();
if (exception != null)
{
exceptionInfo.TypeName = exception.GetType().FullName;
exceptionInfo.Message = exception.Message;
exceptionInfo.HResult = exception.HResult;
exceptionInfo.VerboseMessage = exception.ToString();
}
return exceptionInfo;
return exception != null ? new ExceptionInfo(exception) : ExceptionInfo.Empty;
}

/// <summary>
/// Converts an ILogger state object into a set of key-value pairs (That can be send to a EventSource)
/// </summary>
private IEnumerable<KeyValuePair<string, string>> GetProperties(object state)
private IReadOnlyList<KeyValuePair<string, string>> GetProperties(object state)
{
var arguments = new List<KeyValuePair<string, string>>();
var asKeyValues = state as IEnumerable<KeyValuePair<string, object>>;
if (asKeyValues != null)
if (state is IReadOnlyList<KeyValuePair<string, object>> keyValuePairs)
{
Copy link
Member

Choose a reason for hiding this comment

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

Is there no way to write the object directly as EventData before turning it into a list of string, string?

Copy link
Author

Choose a reason for hiding this comment

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

I suspect there is but it's not easy. I didn't touch methods that take IEnumerable for the first pass.

Copy link
Member

Choose a reason for hiding this comment

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

Ok we need to do that though. I’m ok looking into that next. I think it’s worrhwhile to do.

foreach (var keyValue in asKeyValues)
var arguments = new KeyValuePair<string, string>[keyValuePairs.Count];
for (var i = 0; i < keyValuePairs.Count; i++)
{
if (keyValue.Key != null)
{
arguments.Add(new KeyValuePair<string, string>(keyValue.Key, keyValue.Value?.ToString()));
}
var keyValuePair = keyValuePairs[i];
arguments[i] = new KeyValuePair<string, string>(keyValuePair.Key, keyValuePair.Value?.ToString());
}
return arguments;
}
return arguments;

return Array.Empty<KeyValuePair<string, string>>();
}

private string ToJson(IEnumerable<KeyValuePair<string, string>> keyValues)
private string ToJson(IReadOnlyList<KeyValuePair<string, string>> keyValues)
{
var sw = new StringWriter();
var writer = new JsonTextWriter(sw);
writer.DateFormatString = "O"; // ISO 8601

writer.WriteStartObject();
foreach (var keyValue in keyValues)
for (int i = 0; i < keyValues.Count; i++)
{
var keyValue = keyValues[i];
writer.WritePropertyName(keyValue.Key, true);
writer.WriteValue(keyValue.Value);
}
Expand Down
26 changes: 21 additions & 5 deletions src/Logging/Logging.EventSource/src/ExceptionInfo.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,8 @@
// Copyright (c) .NET Foundation. All rights reserved.
// Copyright (c) .NET Foundation. All rights reserved.
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.

using System;

namespace Microsoft.Extensions.Logging.EventSource
{
/// <summary>
Expand All @@ -9,9 +11,23 @@ namespace Microsoft.Extensions.Logging.EventSource
[System.Diagnostics.Tracing.EventData(Name ="ExceptionInfo")]
internal class ExceptionInfo
{
public string TypeName { get; set; }
public string Message { get; set; }
public int HResult { get; set; }
public string VerboseMessage { get; set; } // This is the ToString() of the Exception
public static ExceptionInfo Empty { get; } = new ExceptionInfo();

private ExceptionInfo()
{
}

public ExceptionInfo(Exception exception)
{
TypeName = exception.GetType().FullName;
Message = exception.Message;
HResult = exception.HResult;
VerboseMessage = exception.ToString();
}

public string TypeName { get; }
public string Message { get; }
public int HResult { get; }
public string VerboseMessage { get; } // This is the ToString() of the Exception
}
}
145 changes: 132 additions & 13 deletions src/Logging/Logging.EventSource/src/LoggingEventSource.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,9 @@

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Diagnostics.Tracing;
using System.Runtime.CompilerServices;
using System.Threading;
using Microsoft.Extensions.Primitives;

Expand Down Expand Up @@ -119,19 +121,40 @@ private LoggingEventSource() : base(EventSourceSettings.EtwSelfDescribingEventFo
/// This only gives you the human reasable formatted message.
/// </summary>
[Event(1, Keywords = Keywords.FormattedMessage, Level = EventLevel.LogAlways)]
internal void FormattedMessage(LogLevel Level, int FactoryID, string LoggerName, string EventId, string FormattedMessage)
internal unsafe void FormattedMessage(LogLevel Level, int FactoryID, string LoggerName, int EventId, string EventName, string FormattedMessage)
{
WriteEvent(1, Level, FactoryID, LoggerName, EventId, FormattedMessage);
if (IsEnabled())
{
fixed (char* loggerName = LoggerName)
fixed (char* eventName = EventName)
fixed (char* formattedMessage = FormattedMessage)
{
const int eventDataCount = 6;
var eventData = stackalloc EventData[eventDataCount];

SetEventData(ref eventData[0], ref Level);
SetEventData(ref eventData[1], ref FactoryID);
SetEventData(ref eventData[2], ref LoggerName, loggerName);
SetEventData(ref eventData[3], ref EventId);
SetEventData(ref eventData[4], ref EventName, eventName);
SetEventData(ref eventData[5], ref FormattedMessage, formattedMessage);

WriteEventCore(1, eventDataCount, eventData);
}
}
}

/// <summary>
/// Message() is called when ILogger.Log() is called. and the Message keyword is active
/// This gives you the logged information in a programatic format (arguments are key-value pairs)
/// </summary>
[Event(2, Keywords = Keywords.Message, Level = EventLevel.LogAlways)]
internal void Message(LogLevel Level, int FactoryID, string LoggerName, string EventId, ExceptionInfo Exception, IEnumerable<KeyValuePair<string, string>> Arguments)
internal void Message(LogLevel Level, int FactoryID, string LoggerName, int EventId, string EventName, ExceptionInfo Exception, IEnumerable<KeyValuePair<string, string>> Arguments)
{
WriteEvent(2, Level, FactoryID, LoggerName, EventId, Exception, Arguments);
if (IsEnabled())
{
WriteEvent(2, Level, FactoryID, LoggerName, EventId, EventName, Exception, Arguments);
}
}

/// <summary>
Expand All @@ -140,31 +163,95 @@ internal void Message(LogLevel Level, int FactoryID, string LoggerName, string E
[Event(3, Keywords = Keywords.Message | Keywords.FormattedMessage, Level = EventLevel.LogAlways, ActivityOptions = EventActivityOptions.Recursive)]
internal void ActivityStart(int ID, int FactoryID, string LoggerName, IEnumerable<KeyValuePair<string, string>> Arguments)
{
WriteEvent(3, ID, FactoryID, LoggerName, Arguments);
if (IsEnabled())
{
WriteEvent(3, ID, FactoryID, LoggerName, Arguments);
}
}

[Event(4, Keywords = Keywords.Message | Keywords.FormattedMessage, Level = EventLevel.LogAlways)]
internal void ActivityStop(int ID, int FactoryID, string LoggerName)
internal unsafe void ActivityStop(int ID, int FactoryID, string LoggerName)
{
WriteEvent(4, ID, FactoryID, LoggerName);
if (IsEnabled())
{
fixed (char* loggerName = LoggerName)
{
const int eventDataCount = 3;
var eventData = stackalloc EventData[eventDataCount];

SetEventData(ref eventData[0], ref ID);
SetEventData(ref eventData[1], ref FactoryID);
SetEventData(ref eventData[2], ref LoggerName, loggerName);

WriteEventCore(4, eventDataCount, eventData);
}
}
}

[Event(5, Keywords = Keywords.JsonMessage, Level = EventLevel.LogAlways)]
internal void MessageJson(LogLevel Level, int FactoryID, string LoggerName, string EventId, string ExceptionJson, string ArgumentsJson)
internal unsafe void MessageJson(LogLevel Level, int FactoryID, string LoggerName, int EventId, string EventName, string ExceptionJson, string ArgumentsJson)
{
WriteEvent(5, Level, FactoryID, LoggerName, EventId, ExceptionJson, ArgumentsJson);
if (IsEnabled())
{
fixed (char* loggerName = LoggerName)
fixed (char* eventName = EventName)
fixed (char* exceptionJson = ExceptionJson)
fixed (char* argumentsJson = ArgumentsJson)
{
const int eventDataCount = 7;
var eventData = stackalloc EventData[eventDataCount];

SetEventData(ref eventData[0], ref Level);
SetEventData(ref eventData[1], ref FactoryID);
SetEventData(ref eventData[2], ref LoggerName, loggerName);
SetEventData(ref eventData[3], ref EventId);
SetEventData(ref eventData[4], ref EventName, eventName);
SetEventData(ref eventData[5], ref ExceptionJson, exceptionJson);
SetEventData(ref eventData[6], ref ArgumentsJson, argumentsJson);

WriteEventCore(5, eventDataCount, eventData);
}
}
}

[Event(6, Keywords = Keywords.JsonMessage | Keywords.FormattedMessage, Level = EventLevel.LogAlways, ActivityOptions = EventActivityOptions.Recursive)]
internal void ActivityJsonStart(int ID, int FactoryID, string LoggerName, string ArgumentsJson)
internal unsafe void ActivityJsonStart(int ID, int FactoryID, string LoggerName, string ArgumentsJson)
{
WriteEvent(6, ID, FactoryID, LoggerName, ArgumentsJson);
if (IsEnabled())
{
fixed (char* loggerName = LoggerName)
fixed (char* argumentsJson = ArgumentsJson)
{
const int eventDataCount = 4;
var eventData = stackalloc EventData[eventDataCount];

SetEventData(ref eventData[0], ref ID);
SetEventData(ref eventData[1], ref FactoryID);
SetEventData(ref eventData[2], ref LoggerName, loggerName);
SetEventData(ref eventData[3], ref ArgumentsJson, argumentsJson);

WriteEventCore(6, eventDataCount, eventData);
}
}
}

[Event(7, Keywords = Keywords.JsonMessage | Keywords.FormattedMessage, Level = EventLevel.LogAlways)]
internal void ActivityJsonStop(int ID, int FactoryID, string LoggerName)
internal unsafe void ActivityJsonStop(int ID, int FactoryID, string LoggerName)
{
WriteEvent(7, ID, FactoryID, LoggerName);
if (IsEnabled())
{
fixed (char* loggerName = LoggerName)
{
const int eventDataCount = 3;
var eventData = stackalloc EventData[eventDataCount];

SetEventData(ref eventData[0], ref ID);
SetEventData(ref eventData[1], ref FactoryID);
SetEventData(ref eventData[2], ref LoggerName, loggerName);

WriteEventCore(7, eventDataCount, eventData);
}
}
}

/// <inheritdoc />
Expand Down Expand Up @@ -355,5 +442,37 @@ internal LoggerFilterRule[] GetFilterRules()
{
return _filterSpec;
}

[NonEvent]
[MethodImpl(MethodImplOptions.AggressiveInlining)]
private static unsafe void SetEventData<T>(ref EventData eventData, ref T value, void* pinnedString = null)
{
if (typeof(T) == typeof(string))
{
var str = value as string;
#if DEBUG
fixed (char* rePinnedString = str)
{
Debug.Assert(pinnedString == rePinnedString);
}
#endif

if (pinnedString != null)
{
eventData.DataPointer = (IntPtr)pinnedString;
eventData.Size = checked((str.Length + 1) * sizeof(char)); // size is specified in bytes, including null wide char
}
else
{
eventData.DataPointer = IntPtr.Zero;
eventData.Size = 0;
}
}
else
{
eventData.DataPointer = (IntPtr)Unsafe.AsPointer(ref value);
eventData.Size = Unsafe.SizeOf<T>();
}
}
}
}
1 change: 1 addition & 0 deletions src/Logging/Logging.EventSource/src/Microsoft.Extensions.Logging.EventSource.csproj
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@
<Description>EventSource/EventListener logger provider implementation for Microsoft.Extensions.Logging.</Description>
<TargetFramework>netstandard2.0</TargetFramework>
<PackageTags>$(PackageTags);EventSource;ETW</PackageTags>
<AllowUnsafeBlocks>true</AllowUnsafeBlocks>
</PropertyGroup>

<ItemGroup>
Expand Down
Loading