Reduce enumerator-allocation when only using CaptureMessageProperties…

… (Without CaptureMessageTemplates)
NLog · Jul 25, 2018 · d096a26 · d096a26
1 parent 28ac193
commit d096a26
Show file tree

Hide file tree

Showing 3 changed files with 54 additions and 14 deletions.
diff --git a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs
@@ -32,33 +32,39 @@ public NLogLogger(Logger logger, NLogProviderOptions options, NLogBeginScopePars
         public void Log<TState>(Microsoft.Extensions.Logging.LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
         {
             var nLogLogLevel = ConvertLogLevel(logLevel);
-            if (!IsEnabled(nLogLogLevel))
+            if (!_logger.IsEnabled(nLogLogLevel))
             {
                 return;
             }
+
             if (formatter == null)
             {
                 throw new ArgumentNullException(nameof(formatter));
             }
 
-            var messageParameters = NLogMessageParameterList.TryParse(_options.CaptureMessageTemplates ? state as IReadOnlyList<KeyValuePair<string, object>> : null);
+            var messageParameters = _options.CaptureMessageTemplates
+                ? NLogMessageParameterList.TryParse(state as IReadOnlyList<KeyValuePair<string, object>>)
+                : null;
 
             LogEventInfo eventInfo =
-                TryParseLogEventInfo(nLogLogLevel, messageParameters) ??
+                TryParseMessageTemplate(nLogLogLevel, messageParameters) ??
                 CreateLogEventInfo(nLogLogLevel, formatter(state, exception), messageParameters);
 
             if (exception != null)
             {
                 eventInfo.Exception = exception;
             }
 
-            CaptureEventId(eventInfo, eventId);
-
-            if (messageParameters == null)
+            if (messageParameters == null && _options.CaptureMessageProperties)
             {
-                CaptureMessageProperties(eventInfo, state);
+                if (_options.CaptureMessageTemplates || !CaptureMessagePropertiesList(eventInfo, state))
+                {
+                    CaptureMessageProperties(eventInfo, state);
+                }
             }
 
+            CaptureEventId(eventInfo, eventId);
+
             _logger.Log(typeof(Microsoft.Extensions.Logging.ILogger), eventInfo);
         }
 
@@ -99,7 +105,7 @@ private LogEventInfo CreateLogEventInfo(LogLevel nLogLogLevel, string message, N
         /// <remarks>
         /// Using the NLog MesageTemplate Parser will hurt performance: 1 x Microsoft Parser - 2 x NLog Parser - 1 x NLog Formatter
         /// </remarks>
-        private LogEventInfo TryParseLogEventInfo(LogLevel nLogLogLevel, NLogMessageParameterList messageParameters)
+        private LogEventInfo TryParseMessageTemplate(LogLevel nLogLogLevel, NLogMessageParameterList messageParameters)
         {
             if (messageParameters?.OriginalMessage != null && (messageParameters.HasComplexParameters || (_options.ParseMessageTemplates && messageParameters.Count > 0)))
             {
@@ -304,7 +310,7 @@ private void CaptureEventId(LogEventInfo eventInfo, EventId eventId)
 
         private void CaptureMessageProperties<TState>(LogEventInfo eventInfo, TState state)
         {
-            if (_options.CaptureMessageProperties && state is IEnumerable<KeyValuePair<string, object>> messageProperties)
+            if (state is IEnumerable<KeyValuePair<string, object>> messageProperties)
             {
                 foreach (var property in messageProperties)
                 {
@@ -316,6 +322,27 @@ private void CaptureMessageProperties<TState>(LogEventInfo eventInfo, TState sta
             }
         }
 
+        private bool CaptureMessagePropertiesList<TState>(LogEventInfo eventInfo, TState state)
+        {
+            if (state is IReadOnlyList<KeyValuePair<string, object>> messageProperties)
+            {
+                for (int i = 0; i < messageProperties.Count; ++i)
+                {
+                    var property = messageProperties[i];
+                    if (String.IsNullOrEmpty(property.Key))
+                        continue;
+
+                    if (i == messageProperties.Count - 1 && property.Key == OriginalFormatPropertyName)
+                        continue;
+
+                    eventInfo.Properties[property.Key] = property.Value;
+                }
+                return true;
+            }
+
+            return false;
+        }
+
         /// <summary>
         /// Is logging enabled for this logger at this <paramref name="logLevel"/>?
         /// </summary>

diff --git a/src/NLog.Extensions.Logging/Logging/NLogLoggerProvider.cs b/src/NLog.Extensions.Logging/Logging/NLogLoggerProvider.cs
@@ -47,10 +47,10 @@ public NLogLoggerProvider(NLogProviderOptions options)
         /// <returns>New Logger</returns>
         public Microsoft.Extensions.Logging.ILogger CreateLogger(string name)
         {
-            var beginScopeExtractor = ((Options?.CaptureMessageProperties ?? true) && (Options?.IncludeScopes ?? true))
+            var beginScopeParser = ((Options?.CaptureMessageProperties ?? true) && (Options?.IncludeScopes ?? true))
                 ? (_beginScopeParser ?? System.Threading.Interlocked.CompareExchange(ref _beginScopeParser, new NLogBeginScopeParser(Options), null))
                 : null;
-            return new NLogLogger(LogManager.GetLogger(name), Options, beginScopeExtractor);
+            return new NLogLogger(LogManager.GetLogger(name), Options, beginScopeParser);
         }
 
         /// <summary>

diff --git a/test/CustomLoggerPropertyTest.cs b/test/CustomLoggerPropertyTest.cs
@@ -10,7 +10,7 @@ namespace NLog.Extensions.Logging.Tests
     public class CustomLoggerPropertyTest : NLogTestBase
     {
         [Fact]
-        public void TestExtraPropertySayHello()
+        public void TestExtraMessageTemplatePropertySayHello()
         {
             ConfigureServiceProvider<CustomLoggerPropertyTestRunner>((s) => s.AddSingleton(typeof(ILogger<>), typeof(SameAssemblyLogger<>)));
             var runner = GetRunner<CustomLoggerPropertyTestRunner>();
@@ -23,7 +23,7 @@ public void TestExtraPropertySayHello()
         }
 
         [Fact]
-        public void TestExtraPropertySayHigh5()
+        public void TestExtraMessageTemplatePropertySayHigh5()
         {
             ConfigureServiceProvider<CustomLoggerPropertyTestRunner>((s) => s.AddSingleton(typeof(ILogger<>), typeof(SameAssemblyLogger<>)));
             var runner = GetRunner<CustomLoggerPropertyTestRunner>();
@@ -35,6 +35,19 @@ public void TestExtraPropertySayHigh5()
             Assert.Equal(@"Hi 5|ActivityId=42", target.Logs[0]);
         }
 
+        [Fact]
+        public void TestExtraMessagePropertySayHi()
+        {
+            ConfigureServiceProvider<CustomLoggerPropertyTestRunner>((s) => s.AddSingleton(typeof(ILogger<>), typeof(SameAssemblyLogger<>)), new NLogProviderOptions() { CaptureMessageTemplates = false });
+            var runner = GetRunner<CustomLoggerPropertyTestRunner>();
+
+            var target = new NLog.Targets.MemoryTarget() { Layout = "${message}|${all-event-properties}" };
+            NLog.Config.SimpleConfigurator.ConfigureForTargetLogging(target);
+            runner.SayHigh5();
+            Assert.Single(target.Logs);
+            Assert.Equal(@"Hi 5|ActivityId=42, 0=5", target.Logs[0]);
+        }
+
         public class SameAssemblyLogger<T> : ILogger<T>
         {
             private readonly Microsoft.Extensions.Logging.ILogger _logger;
@@ -99,7 +112,7 @@ public MyLogEvent(TState state, Func<TState, Exception, string> formatter)
 
             public MyLogEvent<TState> AddProp<T>(string name, T value)
             {
-                _properties.Add(new KeyValuePair<string, object>(name, value));
+                _properties.Insert(0, new KeyValuePair<string, object>(name, value));
                 return this;
             }