From b565946253a5f17b2b242fb9fcc66c8538656d7c Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Tue, 20 Aug 2019 23:39:47 +0200 Subject: [PATCH] NLogLogger - Reduce allocation by not boxing EventId when CaptureEntireEventId = false --- .../NLog.Extensions.Hosting.csproj | 2 +- .../Logging/NLogLogger.cs | 26 ++++++++++++++++--- .../Logging/NLogProviderOptions.cs | 10 ++++++- .../NLog.Extensions.Hosting.Tests.csproj | 2 +- .../Extensions/ConfigureExtensionsTests.cs | 15 ++++++----- .../NLog.Extensions.Logging.Tests/nlog.config | 2 +- 6 files changed, 43 insertions(+), 14 deletions(-) diff --git a/src/NLog.Extensions.Hosting/NLog.Extensions.Hosting.csproj b/src/NLog.Extensions.Hosting/NLog.Extensions.Hosting.csproj index 81b9fad0..32307b53 100644 --- a/src/NLog.Extensions.Hosting/NLog.Extensions.Hosting.csproj +++ b/src/NLog.Extensions.Hosting/NLog.Extensions.Hosting.csproj @@ -33,7 +33,7 @@ Full changelog: https://github.com/NLog/NLog.Extensions.Logging/blob/master/CHAN latest - + diff --git a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs index 3b726e04..90bc5f1b 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs @@ -1,5 +1,6 @@ using System; using System.Collections.Generic; +using System.Linq; using Microsoft.Extensions.Logging; using NLog.MessageTemplates; @@ -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 _eventIdPropertyNames; public NLogLogger(Logger logger, NLogProviderOptions options, NLogBeginScopeParser beginScopeParser) @@ -327,7 +329,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 var eventIdPropertyNames = _eventIdPropertyNames ?? new Tuple(null, null, null); @@ -339,12 +341,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 CreateEventIdPropertyNames(string eventIdSeparator) { var eventIdPropertyNames = new Tuple( diff --git a/src/NLog.Extensions.Logging/Logging/NLogProviderOptions.cs b/src/NLog.Extensions.Logging/Logging/NLogProviderOptions.cs index 1354271d..3177f8af 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogProviderOptions.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogProviderOptions.cs @@ -19,7 +19,7 @@ public class NLogProviderOptions public bool IgnoreEmptyEventId { get; set; } = true; /// - /// Enable structured logging by capturing message template parameters and inject into the -dictionary + /// Enable structured logging by capturing message template parameters with support for "@" and "$". Enables use of ${message:raw=true} /// public bool CaptureMessageTemplates { get; set; } = true; @@ -43,6 +43,14 @@ public class NLogProviderOptions /// public bool ShutdownOnDispose { get; set; } + /// + /// Enable additional capture of the entire as "EventId"-property. + /// + /// + /// Enabling capture of the entire "EventId" will increase memory allocation and gives a performance hit. Faster to use "EventId_Id" + "EventId_Name". + /// + public bool CaptureEntireEventId { get; set; } + /// Initializes a new instance NLogProviderOptions with default values. public NLogProviderOptions() { diff --git a/test/NLog.Extensions.Hosting.Tests/NLog.Extensions.Hosting.Tests.csproj b/test/NLog.Extensions.Hosting.Tests/NLog.Extensions.Hosting.Tests.csproj index b6709160..5e5ea1dd 100644 --- a/test/NLog.Extensions.Hosting.Tests/NLog.Extensions.Hosting.Tests.csproj +++ b/test/NLog.Extensions.Hosting.Tests/NLog.Extensions.Hosting.Tests.csproj @@ -15,7 +15,7 @@ latest - + diff --git a/test/NLog.Extensions.Logging.Tests/Extensions/ConfigureExtensionsTests.cs b/test/NLog.Extensions.Logging.Tests/Extensions/ConfigureExtensionsTests.cs index b00564c1..f566df36 100644 --- a/test/NLog.Extensions.Logging.Tests/Extensions/ConfigureExtensionsTests.cs +++ b/test/NLog.Extensions.Logging.Tests/Extensions/ConfigureExtensionsTests.cs @@ -30,21 +30,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"); diff --git a/test/NLog.Extensions.Logging.Tests/nlog.config b/test/NLog.Extensions.Logging.Tests/nlog.config index c2c6f216..400a4e03 100644 --- a/test/NLog.Extensions.Logging.Tests/nlog.config +++ b/test/NLog.Extensions.Logging.Tests/nlog.config @@ -8,7 +8,7 @@ + layout="${logger}|${uppercase:${level}}|${message} ${exception}|${event-properties:EventId_Id}${event-properties:ParameterCount}${mdlc:item=scope1}" />