Struct alternative to LogEventProperty; optimizations (serilog#1315)

Includes a .NET SDK and AppVeyor build image update.
Twinki14 · Dec 30, 2023 · ab4b0cc · ab4b0cc
1 parent 3b31c78
commit ab4b0cc
Show file tree

Hide file tree

Showing 33 changed files with 381 additions and 81 deletions.
diff --git a/.gitignore b/.gitignore
@@ -331,3 +331,4 @@ ASALocalRun/
 
 # MFractors (Xamarin productivity tool) working folder
 .mfractor/
+*.orig
diff --git a/BuildNativeUWP.ps1 b/BuildNativeUWP.ps1
@@ -5,7 +5,7 @@ param(
 
 echo "build: running .NET Native toolchain for UWP test project"
 
-$msbuild = $(cmd /c where /R 'C:\Program Files (x86)\Microsoft Visual Studio\2017' msbuild.exe | select -First 1)
+$msbuild = $(cmd /c where /R 'C:\Program Files (x86)\Microsoft Visual Studio\2019' msbuild.exe | select -First 1)
 
 if ($customLogger) {
     & $msbuild $proj /logger:"$customLogger" /verbosity:minimal /t:Restore 

diff --git a/Serilog.sln b/Serilog.sln
@@ -8,8 +8,10 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "assets", "assets", "{E9D1B5
 		appveyor.yml = appveyor.yml
 		Build.ps1 = Build.ps1
 		build.sh = build.sh
+		BuildNativeUWP.ps1 = BuildNativeUWP.ps1
 		CHANGES.md = CHANGES.md
 		Directory.Build.props = Directory.Build.props
+		global.json = global.json
 		NuGet.config = NuGet.config
 		README.md = README.md
 		run_perf_tests.sh = run_perf_tests.sh

diff --git a/Serilog.sln.DotSettings b/Serilog.sln.DotSettings
@@ -543,6 +543,7 @@ II.2.12 &lt;HandlesEvent /&gt;&#xD;
 	<s:Boolean x:Key="/Default/Environment/SettingsMigration/IsMigratorApplied/=JetBrains_002EReSharper_002EPsi_002ECSharp_002ECodeStyle_002ECSharpKeepExistingMigration/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/Environment/SettingsMigration/IsMigratorApplied/=JetBrains_002EReSharper_002EPsi_002ECSharp_002ECodeStyle_002ECSharpPlaceEmbeddedOnSameLineMigration/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/Environment/SettingsMigration/IsMigratorApplied/=JetBrains_002EReSharper_002EPsi_002ECSharp_002ECodeStyle_002ECSharpRenamePlacementToArrangementMigration/@EntryIndexedValue">True</s:Boolean>
+	<s:Boolean x:Key="/Default/Environment/SettingsMigration/IsMigratorApplied/=JetBrains_002EReSharper_002EPsi_002ECSharp_002ECodeStyle_002ECSharpUseContinuousIndentInsideBracesMigration/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/Environment/SettingsMigration/IsMigratorApplied/=JetBrains_002EReSharper_002EPsi_002ECSharp_002ECodeStyle_002ESettingsUpgrade_002EAddAccessorOwnerDeclarationBracesMigration/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/Environment/SettingsMigration/IsMigratorApplied/=JetBrains_002EReSharper_002EPsi_002ECSharp_002ECodeStyle_002ESettingsUpgrade_002EAlwaysTreatStructAsNotReorderableMigration/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/Environment/SettingsMigration/IsMigratorApplied/=JetBrains_002EReSharper_002EPsi_002ECSharp_002ECodeStyle_002ESettingsUpgrade_002ECSharpPlaceAttributeOnSameLineMigration/@EntryIndexedValue">True</s:Boolean>
@@ -556,4 +557,9 @@ II.2.12 &lt;HandlesEvent /&gt;&#xD;
 
 
 	<s:String x:Key="/Default/FilterSettingsManager/AttributeFilterXml/@EntryValue">&lt;data /&gt;</s:String>
-	<s:String x:Key="/Default/FilterSettingsManager/CoverageFilterXml/@EntryValue">&lt;data&gt;&lt;IncludeFilters /&gt;&lt;ExcludeFilters /&gt;&lt;/data&gt;</s:String></wpf:ResourceDictionary>
+	<s:String x:Key="/Default/FilterSettingsManager/CoverageFilterXml/@EntryValue">&lt;data&gt;&lt;IncludeFilters /&gt;&lt;ExcludeFilters /&gt;&lt;/data&gt;</s:String>
+	<s:Boolean x:Key="/Default/UserDictionary/Words/=cacheable/@EntryIndexedValue">True</s:Boolean>
+	<s:Boolean x:Key="/Default/UserDictionary/Words/=destructure/@EntryIndexedValue">True</s:Boolean>
+	<s:Boolean x:Key="/Default/UserDictionary/Words/=Enricher/@EntryIndexedValue">True</s:Boolean>
+	<s:Boolean x:Key="/Default/UserDictionary/Words/=Enrichers/@EntryIndexedValue">True</s:Boolean>
+	<s:Boolean x:Key="/Default/UserDictionary/Words/=Serilog/@EntryIndexedValue">True</s:Boolean></wpf:ResourceDictionary>
diff --git a/Setup.ps1 b/Setup.ps1
@@ -0,0 +1,10 @@
+$ErrorActionPreference = "Stop"
+
+$RequiredDotnetVersion =  $(cat ./global.json | convertfrom-json).sdk.version
+
+mkdir "./build"
+Invoke-WebRequest "https://dot.net/v1/dotnet-install.ps1" -OutFile "./build/installcli.ps1"
+& ./build/installcli.ps1 -InstallDir "$pwd/.dotnetcli" -NoPath -Version $RequiredDotnetVersion
+if ($LASTEXITCODE) { exit 1 }
+
+$env:Path = "$pwd/.dotnetcli;$env:Path"
diff --git a/appveyor.yml b/appveyor.yml
@@ -1,18 +1,22 @@
 version: '{build}'
 skip_tags: true
 image:
-  - Visual Studio 2017
-  - Ubuntu
+  - Visual Studio 2019
+  - Ubuntu1804
 configuration: Release
 test: off
+install:
+  - ps: ./Setup.ps1
 build_script:
   - ps: ./Build.ps1
   - ps: ./BuildNativeUWP.ps1
 for:
 -
   matrix:
     only:
-      - image: Ubuntu
+      - image: Ubuntu1804
+  install:
+  - sh setup.sh
   build_script:
   - sh build.sh
 artifacts:

diff --git a/build.sh b/build.sh
@@ -1,6 +1,9 @@
 #!/bin/bash
 
 set -e 
+
+export PATH=$HOME/.dotnetcli:$PATH
+
 dotnet --info
 dotnet --list-sdks
 dotnet restore
@@ -9,13 +12,14 @@ echo "🤖 Attempting to build..."
 for path in src/**/*.csproj; do
     dotnet build -f netstandard1.0 -c Release ${path}
     dotnet build -f netstandard1.3 -c Release ${path}
+    dotnet build -f netstandard2.0 -c Release ${path}
 done
 
 echo "🤖 Running tests..."
 for path in test/*.Tests/*.csproj; do
-    dotnet test -f netcoreapp2.0  -c Release ${path}
+    dotnet test -f netcoreapp2.2  -c Release ${path}
 done
 
 for path in test/*.PerformanceTests/*.PerformanceTests.csproj; do
-    dotnet build -f netcoreapp2.0  -c Release ${path}
+    dotnet build -f netcoreapp2.2  -c Release ${path}
 done
diff --git a/global.json b/global.json
@@ -1,5 +1,5 @@
 {
   "sdk": {
-    "version": "2.1.4"
+    "version": "2.2.300"
   }
 }
diff --git a/setup.sh b/setup.sh
@@ -0,0 +1,7 @@
+#!/bin/bash
+
+sudo apt-get update && sudo apt-get install -y --no-install-recommends jq
+
+RequiredDotnetVersion=$(jq -r '.sdk.version' global.json)
+
+curl https://dot.net/v1/dotnet-install.sh -sSf | bash -s -- --install-dir $HOME/.dotnetcli --no-path --version $RequiredDotnetVersion
diff --git a/src/Serilog/Capturing/MessageTemplateProcessor.cs b/src/Serilog/Capturing/MessageTemplateProcessor.cs
@@ -12,7 +12,6 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
-using System.Collections.Generic;
 using Serilog.Core;
 using Serilog.Core.Pipeline;
 using Serilog.Events;
@@ -32,7 +31,7 @@ public MessageTemplateProcessor(PropertyValueConverter propertyValueConverter)
             _propertyBinder = new PropertyBinder(_propertyValueConverter);
         }
 
-        public void Process(string messageTemplate, object[] messageTemplateParameters, out MessageTemplate parsedTemplate, out IEnumerable<LogEventProperty> properties)
+        public void Process(string messageTemplate, object[] messageTemplateParameters, out MessageTemplate parsedTemplate, out EventProperty[] properties)
         {
             parsedTemplate = _parser.Parse(messageTemplate);
             properties = _propertyBinder.ConstructProperties(parsedTemplate, messageTemplateParameters);
@@ -42,5 +41,10 @@ public LogEventProperty CreateProperty(string name, object value, bool destructu
         {
             return _propertyValueConverter.CreateProperty(name, value, destructureObjects);
         }
+
+        public LogEventPropertyValue CreatePropertyValue(object value, bool destructureObjects = false)
+        {
+            return _propertyValueConverter.CreatePropertyValue(value, destructureObjects);
+        }
     }
 }
diff --git a/src/Serilog/Capturing/PropertyBinder.cs b/src/Serilog/Capturing/PropertyBinder.cs
@@ -13,8 +13,6 @@
 // limitations under the License.
 
 using System;
-using System.Collections.Generic;
-using System.Linq;
 using Serilog.Debugging;
 using Serilog.Events;
 using Serilog.Parsing;
@@ -26,7 +24,7 @@ class PropertyBinder
     {
         readonly PropertyValueConverter _valueConverter;
 
-        static readonly LogEventProperty[] NoProperties = new LogEventProperty[0];
+        static readonly EventProperty[] NoProperties = new EventProperty[0];
 
         public PropertyBinder(PropertyValueConverter valueConverter)
         {
@@ -41,7 +39,7 @@ public PropertyBinder(PropertyValueConverter valueConverter)
         /// represented in the message template.</param>
         /// <returns>A list of properties; if the template is malformed then
         /// this will be empty.</returns>
-        public IEnumerable<LogEventProperty> ConstructProperties(MessageTemplate messageTemplate, object[] messageTemplateParameters)
+        public EventProperty[] ConstructProperties(MessageTemplate messageTemplate, object[] messageTemplateParameters)
         {
             if (messageTemplateParameters == null || messageTemplateParameters.Length == 0)
             {
@@ -57,14 +55,14 @@ public IEnumerable<LogEventProperty> ConstructProperties(MessageTemplate message
             return ConstructNamedProperties(messageTemplate, messageTemplateParameters);
         }
 
-        IEnumerable<LogEventProperty> ConstructPositionalProperties(MessageTemplate template, object[] messageTemplateParameters)
+        EventProperty[] ConstructPositionalProperties(MessageTemplate template, object[] messageTemplateParameters)
         {
             var positionalProperties = template.PositionalProperties;
 
             if (positionalProperties.Length != messageTemplateParameters.Length)
                 SelfLog.WriteLine("Positional property count does not match parameter count: {0}", template);
 
-            var result = new LogEventProperty[messageTemplateParameters.Length];
+            var result = new EventProperty[messageTemplateParameters.Length];
             foreach (var property in positionalProperties)
             {
                 if (property.TryGetPositionalValue(out int position))
@@ -79,7 +77,7 @@ IEnumerable<LogEventProperty> ConstructPositionalProperties(MessageTemplate temp
             var next = 0;
             for (var i = 0; i < result.Length; ++i)
             {
-                if (result[i] != null)
+                if (!result[i].Equals(EventProperty.None))
                 {
                     result[next] = result[i];
                     ++next;
@@ -92,11 +90,11 @@ IEnumerable<LogEventProperty> ConstructPositionalProperties(MessageTemplate temp
             return result;
         }
 
-        IEnumerable<LogEventProperty> ConstructNamedProperties(MessageTemplate template, object[] messageTemplateParameters)
+        EventProperty[] ConstructNamedProperties(MessageTemplate template, object[] messageTemplateParameters)
         {
             var namedProperties = template.NamedProperties;
             if (namedProperties == null)
-                return Enumerable.Empty<LogEventProperty>();
+                return NoProperties;
 
             var matchedRun = namedProperties.Length;
             if (namedProperties.Length != messageTemplateParameters.Length)
@@ -105,7 +103,7 @@ IEnumerable<LogEventProperty> ConstructNamedProperties(MessageTemplate template,
                 SelfLog.WriteLine("Named property count does not match parameter count: {0}", template);
             }
 
-            var result = new LogEventProperty[messageTemplateParameters.Length];
+            var result = new EventProperty[messageTemplateParameters.Length];
             for (var i = 0; i < matchedRun; ++i)
             {
                 var property = template.NamedProperties[i];
@@ -116,14 +114,14 @@ IEnumerable<LogEventProperty> ConstructNamedProperties(MessageTemplate template,
             for (var i = matchedRun; i < messageTemplateParameters.Length; ++i)
             {
                 var value = _valueConverter.CreatePropertyValue(messageTemplateParameters[i]);
-                result[i] = new LogEventProperty("__" + i, value);
+                result[i] = new EventProperty("__" + i, value);
             }
             return result;
         }
 
-        LogEventProperty ConstructProperty(PropertyToken propertyToken, object value)
+        EventProperty ConstructProperty(PropertyToken propertyToken, object value)
         {
-            return new LogEventProperty(
+            return new EventProperty(
                         propertyToken.PropertyName,
                         _valueConverter.CreatePropertyValue(value, propertyToken.Destructuring));
         }

diff --git a/src/Serilog/Capturing/PropertyValueConverter.cs b/src/Serilog/Capturing/PropertyValueConverter.cs
@@ -133,9 +133,6 @@ LogEventPropertyValue CreatePropertyValue(object value, Destructuring destructur
                 return Stringify(value);
             }
 
-            var valueType = value.GetType();
-            DepthLimiter.SetCurrentDepth(depth);
-
             if (destructuring == Destructuring.Destructure)
             {
                 if (value is string stringValue)
@@ -144,12 +141,17 @@ LogEventPropertyValue CreatePropertyValue(object value, Destructuring destructur
                 }
             }
 
+            if (value is string)
+                return new ScalarValue(value);
+
             foreach (var scalarConversionPolicy in _scalarConversionPolicies)
             {
                 if (scalarConversionPolicy.TryConvertToScalar(value, out var converted))
                     return converted;
             }
 
+            DepthLimiter.SetCurrentDepth(depth);
+
             if (destructuring == Destructuring.Destructure)
             {
                 foreach (var destructuringPolicy in _destructuringPolicies)
@@ -159,6 +161,8 @@ LogEventPropertyValue CreatePropertyValue(object value, Destructuring destructur
                 }
             }
 
+            var valueType = value.GetType();
+
             if (TryConvertEnumerable(value, destructuring, valueType, out var enumerableResult))
                 return enumerableResult;
 

diff --git a/src/Serilog/Core/Enrichers/FixedPropertyEnricher.cs b/src/Serilog/Core/Enrichers/FixedPropertyEnricher.cs
@@ -19,17 +19,18 @@ namespace Serilog.Core.Enrichers
 {
     class FixedPropertyEnricher : ILogEventEnricher
     {
-        readonly LogEventProperty _logEventProperty;
+        readonly EventProperty _eventProperty;
 
-        public FixedPropertyEnricher(LogEventProperty logEventProperty)
+        public FixedPropertyEnricher(in EventProperty eventProperty)
         {
-            _logEventProperty = logEventProperty ?? throw new ArgumentNullException(nameof(logEventProperty));
+            if (eventProperty.Equals(EventProperty.None)) throw new ArgumentNullException(nameof(eventProperty));
+            _eventProperty = eventProperty;
         }
 
         public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
         {
             if (logEvent == null) throw new ArgumentNullException(nameof(logEvent));
-            logEvent.AddPropertyIfAbsent(_logEventProperty);
+            logEvent.AddPropertyIfAbsent(_eventProperty);
         }
     }
-}
+}
diff --git a/src/Serilog/Core/Logger.cs b/src/Serilog/Core/Logger.cs
@@ -14,6 +14,7 @@
 
 using System;
 using System.Collections.Generic;
+using System.Linq;
 using Serilog.Capturing;
 using Serilog.Core.Enrichers;
 using Serilog.Core.Pipeline;
@@ -32,6 +33,7 @@ namespace Serilog.Core
     public sealed class Logger : ILogger, ILogEventSink, IDisposable
     {
         static readonly object[] NoPropertyValues = new object[0];
+        static readonly LogEventProperty[] NoProperties = new LogEventProperty[0];
 
         readonly MessageTemplateProcessor _messageTemplateProcessor;
         readonly ILogEventSink _sink;
@@ -141,10 +143,9 @@ public ILogger ForContext(string propertyName, object value, bool destructureObj
             }
 
             // It'd be nice to do the destructuring lazily, but unfortunately `value` may be mutated between
-            // now and the first log event written...
-            // A future optimization opportunity may be to implement ILogEventEnricher on LogEventProperty to
-            // remove one more allocation.
-            var enricher = new FixedPropertyEnricher(_messageTemplateProcessor.CreateProperty(propertyName, value, destructureObjects));
+            // now and the first log event written.
+            var propertyValue = _messageTemplateProcessor.CreatePropertyValue(value, destructureObjects);
+            var enricher = new FixedPropertyEnricher(new EventProperty(propertyName, propertyValue));
 
             var minimumLevel = _minimumLevel;
             var levelSwitch = _levelSwitch;
@@ -367,7 +368,7 @@ public void Write(LogEventLevel level, Exception exception, string messageTempla
                 propertyValues.GetType() != typeof(object[]))
                 propertyValues = new object[] { propertyValues };
 
-            _messageTemplateProcessor.Process(messageTemplate, propertyValues, out MessageTemplate parsedTemplate, out IEnumerable<LogEventProperty> boundProperties);
+            _messageTemplateProcessor.Process(messageTemplate, propertyValues, out MessageTemplate parsedTemplate, out var boundProperties);
 
             var logEvent = new LogEvent(DateTimeOffset.Now, level, exception, parsedTemplate, boundProperties);
             Dispatch(logEvent);
@@ -1333,7 +1334,11 @@ public bool BindMessageTemplate(string messageTemplate, object[] propertyValues,
                 return false;
             }
 
-            _messageTemplateProcessor.Process(messageTemplate, propertyValues, out parsedTemplate, out boundProperties);
+            _messageTemplateProcessor.Process(messageTemplate, propertyValues, out parsedTemplate, out var boundEventProperties);
+            boundProperties = boundEventProperties.Length == 0 ?
+                NoProperties :
+                boundEventProperties.Select(p => new LogEventProperty(p));
+
             return true;
         }
 

diff --git a/src/Serilog/Core/Sinks/SecondaryLoggerSink.cs b/src/Serilog/Core/Sinks/SecondaryLoggerSink.cs
@@ -40,13 +40,7 @@ public void Emit(LogEvent logEvent)
         {
             if (logEvent == null) throw new ArgumentNullException(nameof(logEvent));
 
-            var copy = new LogEvent(
-                logEvent.Timestamp,
-                logEvent.Level,
-                logEvent.Exception,
-                logEvent.MessageTemplate,
-                logEvent.Properties.Select(p => new LogEventProperty(p.Key, p.Value)));
-
+            var copy = logEvent.Copy();
             _logger.Write(copy);
         }