NLogLogger - Reduce allocation by not boxing EventId when CaptureEnti…

…reEventId = false
NLog · Mar 21, 2021 · 8a6d8d3 · 8a6d8d3
1 parent a047ac1
commit 8a6d8d3
Show file tree

Hide file tree

Showing 4 changed files with 49 additions and 17 deletions.
diff --git 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<string, string, string> _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 <see cref="NLogProviderOptions.EventIdSeparator"/>
                 var eventIdPropertyNames = _eventIdPropertyNames ?? new Tuple<string, string, string>(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<string, string, string> CreateEventIdPropertyNames(string eventIdSeparator)
         {
             var eventIdPropertyNames = new Tuple<string, string, string>(

diff --git 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;
 
         /// <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;
 
@@ -68,6 +68,14 @@ public class NLogProviderOptions
         /// <remarks>This option affects the building of service configuration, so assigning it from appsettings.json has no effect (loaded after).</remarks>
         public bool ReplaceLoggerFactory { 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()
         {

diff --git a/test/NLog.Extensions.Logging.Tests/Extensions/ConfigureExtensionsTests.cs b/test/NLog.Extensions.Logging.Tests/Extensions/ConfigureExtensionsTests.cs
@@ -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");
@@ -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);

diff --git a/test/NLog.Extensions.Logging.Tests/nlog.config b/test/NLog.Extensions.Logging.Tests/nlog.config
@@ -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>