Skip to content

Commit 091ee13

Browse files
pakrympakrym
authored
Reduce event source logger allocations (#870)
1 parent a2f2814 commit 091ee13

9 files changed

+351
-104
lines changed

‎src/Logging/Logging.EventSource/src/EventSourceLogger.cs

Lines changed: 30 additions & 31 deletions
Original file line numberDiff line numberDiff line change
@@ -62,21 +62,23 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
6262
logLevel,
6363
_factoryID,
6464
CategoryName,
65-
eventId.ToString(),
65+
eventId.Id,
66+
eventId.Name,
6667
message);
6768
}
6869

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

7576
_eventSource.Message(
7677
logLevel,
7778
_factoryID,
7879
CategoryName,
79-
eventId.ToString(),
80+
eventId.Id,
81+
eventId.Name,
8082
exceptionInfo,
8183
arguments);
8284
}
@@ -88,7 +90,7 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
8890
if (exception != null)
8991
{
9092
var exceptionInfo = GetExceptionInfo(exception);
91-
var exceptionInfoData = new KeyValuePair<string, string>[]
93+
var exceptionInfoData = new []
9294
{
9395
new KeyValuePair<string, string>("TypeName", exceptionInfo.TypeName),
9496
new KeyValuePair<string, string>("Message", exceptionInfo.Message),
@@ -97,12 +99,13 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
9799
};
98100
exceptionJson = ToJson(exceptionInfoData);
99101
}
100-
IEnumerable<KeyValuePair<string, string>> arguments = GetProperties(state);
102+
var arguments = GetProperties(state);
101103
_eventSource.MessageJson(
102104
logLevel,
103105
_factoryID,
104106
CategoryName,
105-
eventId.ToString(),
107+
eventId.Id,
108+
eventId.Name,
106109
exceptionJson,
107110
ToJson(arguments));
108111
}
@@ -120,16 +123,20 @@ public IDisposable BeginScope<TState>(TState state)
120123
// If JsonMessage is on, use JSON format
121124
if (_eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.JsonMessage))
122125
{
123-
IEnumerable<KeyValuePair<string, string>> arguments = GetProperties(state);
126+
var arguments = GetProperties(state);
124127
_eventSource.ActivityJsonStart(id, _factoryID, CategoryName, ToJson(arguments));
125128
return new ActivityScope(_eventSource, CategoryName, id, _factoryID, true);
126129
}
127-
else
130+
131+
if (_eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.Message) ||
132+
_eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.FormattedMessage))
128133
{
129-
IEnumerable<KeyValuePair<string, string>> arguments = GetProperties(state);
134+
var arguments = GetProperties(state);
130135
_eventSource.ActivityStart(id, _factoryID, CategoryName, arguments);
131136
return new ActivityScope(_eventSource, CategoryName, id, _factoryID, false);
132137
}
138+
139+
return NullScope.Instance;
133140
}
134141

135142
/// <summary>
@@ -174,46 +181,38 @@ public void Dispose()
174181
/// <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>
175182
private ExceptionInfo GetExceptionInfo(Exception exception)
176183
{
177-
var exceptionInfo = new ExceptionInfo();
178-
if (exception != null)
179-
{
180-
exceptionInfo.TypeName = exception.GetType().FullName;
181-
exceptionInfo.Message = exception.Message;
182-
exceptionInfo.HResult = exception.HResult;
183-
exceptionInfo.VerboseMessage = exception.ToString();
184-
}
185-
return exceptionInfo;
184+
return exception != null ? new ExceptionInfo(exception) : ExceptionInfo.Empty;
186185
}
187186

188187
/// <summary>
189188
/// Converts an ILogger state object into a set of key-value pairs (That can be send to a EventSource)
190189
/// </summary>
191-
private IEnumerable<KeyValuePair<string, string>> GetProperties(object state)
190+
private IReadOnlyList<KeyValuePair<string, string>> GetProperties(object state)
192191
{
193-
var arguments = new List<KeyValuePair<string, string>>();
194-
var asKeyValues = state as IEnumerable<KeyValuePair<string, object>>;
195-
if (asKeyValues != null)
192+
if (state is IReadOnlyList<KeyValuePair<string, object>> keyValuePairs)
196193
{
197-
foreach (var keyValue in asKeyValues)
194+
var arguments = new KeyValuePair<string, string>[keyValuePairs.Count];
195+
for (var i = 0; i < keyValuePairs.Count; i++)
198196
{
199-
if (keyValue.Key != null)
200-
{
201-
arguments.Add(new KeyValuePair<string, string>(keyValue.Key, keyValue.Value?.ToString()));
202-
}
197+
var keyValuePair = keyValuePairs[i];
198+
arguments[i] = new KeyValuePair<string, string>(keyValuePair.Key, keyValuePair.Value?.ToString());
203199
}
200+
return arguments;
204201
}
205-
return arguments;
202+
203+
return Array.Empty<KeyValuePair<string, string>>();
206204
}
207205

208-
private string ToJson(IEnumerable<KeyValuePair<string, string>> keyValues)
206+
private string ToJson(IReadOnlyList<KeyValuePair<string, string>> keyValues)
209207
{
210208
var sw = new StringWriter();
211209
var writer = new JsonTextWriter(sw);
212210
writer.DateFormatString = "O"; // ISO 8601
213211

214212
writer.WriteStartObject();
215-
foreach (var keyValue in keyValues)
213+
for (int i = 0; i < keyValues.Count; i++)
216214
{
215+
var keyValue = keyValues[i];
217216
writer.WritePropertyName(keyValue.Key, true);
218217
writer.WriteValue(keyValue.Value);
219218
}

‎src/Logging/Logging.EventSource/src/ExceptionInfo.cs

Lines changed: 21 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,8 @@
1-
// Copyright (c) .NET Foundation. All rights reserved.
1+
// Copyright (c) .NET Foundation. All rights reserved.
22
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
33

4+
using System;
5+
46
namespace Microsoft.Extensions.Logging.EventSource
57
{
68
/// <summary>
@@ -9,9 +11,23 @@ namespace Microsoft.Extensions.Logging.EventSource
911
[System.Diagnostics.Tracing.EventData(Name ="ExceptionInfo")]
1012
internal class ExceptionInfo
1113
{
12-
public string TypeName { get; set; }
13-
public string Message { get; set; }
14-
public int HResult { get; set; }
15-
public string VerboseMessage { get; set; } // This is the ToString() of the Exception
14+
public static ExceptionInfo Empty { get; } = new ExceptionInfo();
15+
16+
private ExceptionInfo()
17+
{
18+
}
19+
20+
public ExceptionInfo(Exception exception)
21+
{
22+
TypeName = exception.GetType().FullName;
23+
Message = exception.Message;
24+
HResult = exception.HResult;
25+
VerboseMessage = exception.ToString();
26+
}
27+
28+
public string TypeName { get; }
29+
public string Message { get; }
30+
public int HResult { get; }
31+
public string VerboseMessage { get; } // This is the ToString() of the Exception
1632
}
1733
}

‎src/Logging/Logging.EventSource/src/LoggingEventSource.cs

Lines changed: 132 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,9 @@
33

44
using System;
55
using System.Collections.Generic;
6+
using System.Diagnostics;
67
using System.Diagnostics.Tracing;
8+
using System.Runtime.CompilerServices;
79
using System.Threading;
810
using Microsoft.Extensions.Primitives;
911

@@ -119,19 +121,40 @@ private LoggingEventSource() : base(EventSourceSettings.EtwSelfDescribingEventFo
119121
/// This only gives you the human reasable formatted message.
120122
/// </summary>
121123
[Event(1, Keywords = Keywords.FormattedMessage, Level = EventLevel.LogAlways)]
122-
internal void FormattedMessage(LogLevel Level, int FactoryID, string LoggerName, string EventId, string FormattedMessage)
124+
internal unsafe void FormattedMessage(LogLevel Level, int FactoryID, string LoggerName, int EventId, string EventName, string FormattedMessage)
123125
{
124-
WriteEvent(1, Level, FactoryID, LoggerName, EventId, FormattedMessage);
126+
if (IsEnabled())
127+
{
128+
fixed (char* loggerName = LoggerName)
129+
fixed (char* eventName = EventName)
130+
fixed (char* formattedMessage = FormattedMessage)
131+
{
132+
const int eventDataCount = 6;
133+
var eventData = stackalloc EventData[eventDataCount];
134+
135+
SetEventData(ref eventData[0], ref Level);
136+
SetEventData(ref eventData[1], ref FactoryID);
137+
SetEventData(ref eventData[2], ref LoggerName, loggerName);
138+
SetEventData(ref eventData[3], ref EventId);
139+
SetEventData(ref eventData[4], ref EventName, eventName);
140+
SetEventData(ref eventData[5], ref FormattedMessage, formattedMessage);
141+
142+
WriteEventCore(1, eventDataCount, eventData);
143+
}
144+
}
125145
}
126146

127147
/// <summary>
128148
/// Message() is called when ILogger.Log() is called. and the Message keyword is active
129149
/// This gives you the logged information in a programatic format (arguments are key-value pairs)
130150
/// </summary>
131151
[Event(2, Keywords = Keywords.Message, Level = EventLevel.LogAlways)]
132-
internal void Message(LogLevel Level, int FactoryID, string LoggerName, string EventId, ExceptionInfo Exception, IEnumerable<KeyValuePair<string, string>> Arguments)
152+
internal void Message(LogLevel Level, int FactoryID, string LoggerName, int EventId, string EventName, ExceptionInfo Exception, IEnumerable<KeyValuePair<string, string>> Arguments)
133153
{
134-
WriteEvent(2, Level, FactoryID, LoggerName, EventId, Exception, Arguments);
154+
if (IsEnabled())
155+
{
156+
WriteEvent(2, Level, FactoryID, LoggerName, EventId, EventName, Exception, Arguments);
157+
}
135158
}
136159

137160
/// <summary>
@@ -140,31 +163,95 @@ internal void Message(LogLevel Level, int FactoryID, string LoggerName, string E
140163
[Event(3, Keywords = Keywords.Message | Keywords.FormattedMessage, Level = EventLevel.LogAlways, ActivityOptions = EventActivityOptions.Recursive)]
141164
internal void ActivityStart(int ID, int FactoryID, string LoggerName, IEnumerable<KeyValuePair<string, string>> Arguments)
142165
{
143-
WriteEvent(3, ID, FactoryID, LoggerName, Arguments);
166+
if (IsEnabled())
167+
{
168+
WriteEvent(3, ID, FactoryID, LoggerName, Arguments);
169+
}
144170
}
145171

146172
[Event(4, Keywords = Keywords.Message | Keywords.FormattedMessage, Level = EventLevel.LogAlways)]
147-
internal void ActivityStop(int ID, int FactoryID, string LoggerName)
173+
internal unsafe void ActivityStop(int ID, int FactoryID, string LoggerName)
148174
{
149-
WriteEvent(4, ID, FactoryID, LoggerName);
175+
if (IsEnabled())
176+
{
177+
fixed (char* loggerName = LoggerName)
178+
{
179+
const int eventDataCount = 3;
180+
var eventData = stackalloc EventData[eventDataCount];
181+
182+
SetEventData(ref eventData[0], ref ID);
183+
SetEventData(ref eventData[1], ref FactoryID);
184+
SetEventData(ref eventData[2], ref LoggerName, loggerName);
185+
186+
WriteEventCore(4, eventDataCount, eventData);
187+
}
188+
}
150189
}
151190

152191
[Event(5, Keywords = Keywords.JsonMessage, Level = EventLevel.LogAlways)]
153-
internal void MessageJson(LogLevel Level, int FactoryID, string LoggerName, string EventId, string ExceptionJson, string ArgumentsJson)
192+
internal unsafe void MessageJson(LogLevel Level, int FactoryID, string LoggerName, int EventId, string EventName, string ExceptionJson, string ArgumentsJson)
154193
{
155-
WriteEvent(5, Level, FactoryID, LoggerName, EventId, ExceptionJson, ArgumentsJson);
194+
if (IsEnabled())
195+
{
196+
fixed (char* loggerName = LoggerName)
197+
fixed (char* eventName = EventName)
198+
fixed (char* exceptionJson = ExceptionJson)
199+
fixed (char* argumentsJson = ArgumentsJson)
200+
{
201+
const int eventDataCount = 7;
202+
var eventData = stackalloc EventData[eventDataCount];
203+
204+
SetEventData(ref eventData[0], ref Level);
205+
SetEventData(ref eventData[1], ref FactoryID);
206+
SetEventData(ref eventData[2], ref LoggerName, loggerName);
207+
SetEventData(ref eventData[3], ref EventId);
208+
SetEventData(ref eventData[4], ref EventName, eventName);
209+
SetEventData(ref eventData[5], ref ExceptionJson, exceptionJson);
210+
SetEventData(ref eventData[6], ref ArgumentsJson, argumentsJson);
211+
212+
WriteEventCore(5, eventDataCount, eventData);
213+
}
214+
}
156215
}
157216

158217
[Event(6, Keywords = Keywords.JsonMessage | Keywords.FormattedMessage, Level = EventLevel.LogAlways, ActivityOptions = EventActivityOptions.Recursive)]
159-
internal void ActivityJsonStart(int ID, int FactoryID, string LoggerName, string ArgumentsJson)
218+
internal unsafe void ActivityJsonStart(int ID, int FactoryID, string LoggerName, string ArgumentsJson)
160219
{
161-
WriteEvent(6, ID, FactoryID, LoggerName, ArgumentsJson);
220+
if (IsEnabled())
221+
{
222+
fixed (char* loggerName = LoggerName)
223+
fixed (char* argumentsJson = ArgumentsJson)
224+
{
225+
const int eventDataCount = 4;
226+
var eventData = stackalloc EventData[eventDataCount];
227+
228+
SetEventData(ref eventData[0], ref ID);
229+
SetEventData(ref eventData[1], ref FactoryID);
230+
SetEventData(ref eventData[2], ref LoggerName, loggerName);
231+
SetEventData(ref eventData[3], ref ArgumentsJson, argumentsJson);
232+
233+
WriteEventCore(6, eventDataCount, eventData);
234+
}
235+
}
162236
}
163237

164238
[Event(7, Keywords = Keywords.JsonMessage | Keywords.FormattedMessage, Level = EventLevel.LogAlways)]
165-
internal void ActivityJsonStop(int ID, int FactoryID, string LoggerName)
239+
internal unsafe void ActivityJsonStop(int ID, int FactoryID, string LoggerName)
166240
{
167-
WriteEvent(7, ID, FactoryID, LoggerName);
241+
if (IsEnabled())
242+
{
243+
fixed (char* loggerName = LoggerName)
244+
{
245+
const int eventDataCount = 3;
246+
var eventData = stackalloc EventData[eventDataCount];
247+
248+
SetEventData(ref eventData[0], ref ID);
249+
SetEventData(ref eventData[1], ref FactoryID);
250+
SetEventData(ref eventData[2], ref LoggerName, loggerName);
251+
252+
WriteEventCore(7, eventDataCount, eventData);
253+
}
254+
}
168255
}
169256

170257
/// <inheritdoc />
@@ -355,5 +442,37 @@ internal LoggerFilterRule[] GetFilterRules()
355442
{
356443
return _filterSpec;
357444
}
445+
446+
[NonEvent]
447+
[MethodImpl(MethodImplOptions.AggressiveInlining)]
448+
private static unsafe void SetEventData<T>(ref EventData eventData, ref T value, void* pinnedString = null)
449+
{
450+
if (typeof(T) == typeof(string))
451+
{
452+
var str = value as string;
453+
#if DEBUG
454+
fixed (char* rePinnedString = str)
455+
{
456+
Debug.Assert(pinnedString == rePinnedString);
457+
}
458+
#endif
459+
460+
if (pinnedString != null)
461+
{
462+
eventData.DataPointer = (IntPtr)pinnedString;
463+
eventData.Size = checked((str.Length + 1) * sizeof(char)); // size is specified in bytes, including null wide char
464+
}
465+
else
466+
{
467+
eventData.DataPointer = IntPtr.Zero;
468+
eventData.Size = 0;
469+
}
470+
}
471+
else
472+
{
473+
eventData.DataPointer = (IntPtr)Unsafe.AsPointer(ref value);
474+
eventData.Size = Unsafe.SizeOf<T>();
475+
}
476+
}
358477
}
359478
}

‎src/Logging/Logging.EventSource/src/Microsoft.Extensions.Logging.EventSource.csproj

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
<Description>EventSource/EventListener logger provider implementation for Microsoft.Extensions.Logging.</Description>
55
<TargetFramework>netstandard2.0</TargetFramework>
66
<PackageTags>$(PackageTags);EventSource;ETW</PackageTags>
7+
<AllowUnsafeBlocks>true</AllowUnsafeBlocks>
78
</PropertyGroup>
89

910
<ItemGroup>

0 commit comments

Comments
 (0)