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

NLogLogger - Reduce allocation by not boxing EventId when CaptureEntireEventId = false #319

Merged
merged 1 commit into from
Aug 26, 2021
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
26 changes: 22 additions & 4 deletions src/NLog.Extensions.Logging/Logging/NLogLogger.cs
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
using System;
using System.Collections.Generic;
using System.Linq;
using Microsoft.Extensions.Logging;
using NLog.MessageTemplates;

Expand All @@ -18,6 +19,7 @@ internal class NLogLogger : Microsoft.Extensions.Logging.ILogger
internal const string OriginalFormatPropertyName = "{OriginalFormat}";
private static readonly object EmptyEventId = default(EventId); // Cache boxing of empty EventId-struct
private static readonly object ZeroEventId = default(EventId).Id; // Cache boxing of zero EventId-Value
private static readonly object[] EventIdBoxing = Enumerable.Range(0, 50).Select(v => (object)v).ToArray(); // Most EventIds in the ASP.NET Core Engine is below 50
private Tuple<string, string, string> _eventIdPropertyNames;

public NLogLogger(Logger logger, NLogProviderOptions options, NLogBeginScopeParser beginScopeParser)
Expand Down Expand Up @@ -326,7 +328,7 @@ private static void SetLogEventMessageFormatter(LogEventInfo logEvent, NLogMessa

private void CaptureEventId(LogEventInfo eventInfo, EventId eventId)
{
if (!_options.IgnoreEmptyEventId || eventId.Id != 0 || !String.IsNullOrEmpty(eventId.Name))
if (_options.CaptureMessageProperties && (!_options.IgnoreEmptyEventId || eventId.Id != 0 || !String.IsNullOrEmpty(eventId.Name)))
{
// Attempt to reuse the same string-allocations based on the current <see cref="NLogProviderOptions.EventIdSeparator"/>
var eventIdPropertyNames = _eventIdPropertyNames ?? new Tuple<string, string, string>(null, null, null);
Expand All @@ -338,12 +340,28 @@ private void CaptureEventId(LogEventInfo eventInfo, EventId eventId)
}

var idIsZero = eventId.Id == 0;
eventInfo.Properties[eventIdPropertyNames.Item2] = idIsZero ? ZeroEventId : eventId.Id;
eventInfo.Properties[eventIdPropertyNames.Item3] = eventId.Name;
eventInfo.Properties["EventId"] = idIsZero && eventId.Name == null ? EmptyEventId : eventId;
var eventIdObj = idIsZero ? ZeroEventId : GetEventId(eventId.Id);
eventInfo.Properties[eventIdPropertyNames.Item2] = eventIdObj;
if (_options.CaptureEntireEventId)
{
eventInfo.Properties[eventIdPropertyNames.Item3] = eventId.Name;
eventInfo.Properties["EventId"] = idIsZero && eventId.Name == null ? EmptyEventId : eventId;
}
else if (!string.IsNullOrEmpty(eventId.Name))
{
eventInfo.Properties[eventIdPropertyNames.Item3] = eventId.Name;
}
}
}

private static object GetEventId(int eventId)
{
if (eventId >= 0 && eventId < EventIdBoxing.Length)
return EventIdBoxing[eventId];
else
return eventId;
}

private static Tuple<string, string, string> CreateEventIdPropertyNames(string eventIdSeparator)
{
var eventIdPropertyNames = new Tuple<string, string, string>(
Expand Down
10 changes: 9 additions & 1 deletion src/NLog.Extensions.Logging/Logging/NLogProviderOptions.cs
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,7 @@ public class NLogProviderOptions
public bool IgnoreEmptyEventId { get; set; } = true;

/// <summary>
/// Enable structured logging by capturing message template parameters and inject into the <see cref="LogEventInfo.Properties" />-dictionary
/// Enable structured logging by capturing message template parameters with support for "@" and "$". Enables use of ${message:raw=true}
/// </summary>
public bool CaptureMessageTemplates { get; set; } = true;

Expand Down Expand Up @@ -74,6 +74,14 @@ public class NLogProviderOptions
/// <remarks>Will only attempt to load NLog-LoggingConfiguration if valid section-name, and NLog-LoggingConfiguration has not been loaded already.</remarks>
public string LoggingConfigurationSectionName { get; set; }

/// <summary>
/// Enable additional capture of the entire <see cref="Microsoft.Extensions.Logging.EventId"/> as "EventId"-property.
/// </summary>
/// <remarks>
/// Enabling capture of the entire "EventId" will increase memory allocation and gives a performance hit. Faster to use "EventId_Id" + "EventId_Name".
/// </remarks>
public bool CaptureEntireEventId { get; set; }

/// <summary>Initializes a new instance NLogProviderOptions with default values.</summary>
public NLogProviderOptions()
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -31,21 +31,24 @@ public void AddNLog_LoggerFactory_LogInfo_ShouldLogToNLog()
}

[Theory]
[InlineData("EventId", "eventId2")]
[InlineData("EventId_Name", "eventId2")]
[InlineData("EventId_Id", "2")]
[InlineData("EventId", "eventId_2", true)]
[InlineData("EventId_Name", "eventId_2", true)]
[InlineData("EventId_Id", "2", true)]
[InlineData("EventId", "", false)]
[InlineData("EventId_Name", "eventId_2", false)]
[InlineData("EventId_Id", "2", false)]
[Obsolete("Instead use ILoggingBuilder.AddNLog() or IHostBuilder.UseNLog()")]
public void AddNLog_LoggerFactory_LogInfoWithEventId_ShouldLogToNLogWithEventId(string eventPropery, string expectedEventInLog)
public void AddNLog_LoggerFactory_LogInfoWithEventId_ShouldLogToNLogWithEventId(string eventPropery, string expectedEventInLog, bool captureEntireEventId)
{
// Arrange
var loggerFactory = new LoggerFactory();
var config = CreateConfigWithMemoryTarget(out var memoryTarget, $"${{event-properties:{eventPropery}}} - ${{message}}");

// Act
loggerFactory.AddNLog(new NLogProviderOptions { EventIdSeparator = "_" });
loggerFactory.AddNLog(new NLogProviderOptions { EventIdSeparator = "_", CaptureEntireEventId = captureEntireEventId });
LogManager.Configuration = config;
var logger = loggerFactory.CreateLogger("logger1");
logger.LogInformation(new EventId(2, "eventId2"), "test message with {0} arg", 1);
logger.LogInformation(new EventId(2, "eventId_2"), "test message with {0} arg", 1);

// Assert
AssertSingleMessage(memoryTarget, $"{expectedEventInLog} - test message with 1 arg");
Expand Down Expand Up @@ -95,15 +98,18 @@ public void AddNLog_LoggingBuilder_LogInfo_ShouldLogToNLog()
}

[Theory]
[InlineData("EventId", "eventId2")]
[InlineData("EventId_Name", "eventId2")]
[InlineData("EventId_Id", "2")]
public void AddNLog_LoggingBuilder_LogInfoWithEventId_ShouldLogToNLogWithEventId(string eventPropery, string expectedEventInLog)
[InlineData("EventId", "eventId2", true)]
[InlineData("EventId_Name", "eventId2", true)]
[InlineData("EventId_Id", "2", true)]
[InlineData("EventId", "", false)]
[InlineData("EventId_Name", "eventId2", false)]
[InlineData("EventId_Id", "2", false)]
public void AddNLog_LoggingBuilder_LogInfoWithEventId_ShouldLogToNLogWithEventId(string eventPropery, string expectedEventInLog, bool captureEntireEventId)
{
// Arrange
ILoggingBuilder builder = new LoggingBuilderStub();
var config = CreateConfigWithMemoryTarget(out var memoryTarget, $"${{event-properties:{eventPropery}}} - ${{message}}");
var options = new NLogProviderOptions { EventIdSeparator = "_" };
var options = new NLogProviderOptions { EventIdSeparator = "_", CaptureEntireEventId = captureEntireEventId };

// Act
builder.AddNLog(config, options);
Expand Down
2 changes: 1 addition & 1 deletion test/NLog.Extensions.Logging.Tests/nlog.config
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@
<targets>
<!-- write logs to file -->
<target xsi:type="Memory" name="target1"
layout="${logger}|${uppercase:${level}}|${message} ${exception}|${event-properties:EventId}${event-properties:ParameterCount}${mdlc:item=scope1}" />
layout="${logger}|${uppercase:${level}}|${message} ${exception}|${event-properties:EventId_Id}${event-properties:ParameterCount}${mdlc:item=scope1}" />

</targets>

Expand Down