Cache low-numbered numeric event ids to reduce allocations

serilog-extensions-logging.sln

@@ -1,7 +1,7 @@
 
 Microsoft Visual Studio Solution File, Format Version 12.00
-# Visual Studio 15
-VisualStudioVersion = 15.0.26730.10
+# Visual Studio Version 16
+VisualStudioVersion = 16.0.29209.62
 MinimumVisualStudioVersion = 10.0.40219.1
 Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "src", "src", "{A1893BD1-333D-4DFE-A0F0-DDBB2FE526E0}"
 EndProject
@@ -24,6 +24,8 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "assets", "assets", "{9C21B9
 		assets\Serilog.snk = assets\Serilog.snk
 	EndProjectSection
 EndProject
+Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Serilog.Extensions.Logging.Benchmarks", "test\Serilog.Extensions.Logging.Benchmarks\Serilog.Extensions.Logging.Benchmarks.csproj", "{6D5986FF-EECD-4E75-8BC6-A5F78AB549B2}"
+EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
 		Debug|Any CPU = Debug|Any CPU
@@ -42,6 +44,10 @@ Global
 		{65357FBC-9BC4-466D-B621-1C3A19BC2A78}.Debug|Any CPU.Build.0 = Debug|Any CPU
 		{65357FBC-9BC4-466D-B621-1C3A19BC2A78}.Release|Any CPU.ActiveCfg = Release|Any CPU
 		{65357FBC-9BC4-466D-B621-1C3A19BC2A78}.Release|Any CPU.Build.0 = Release|Any CPU
+		{6D5986FF-EECD-4E75-8BC6-A5F78AB549B2}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{6D5986FF-EECD-4E75-8BC6-A5F78AB549B2}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{6D5986FF-EECD-4E75-8BC6-A5F78AB549B2}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{6D5986FF-EECD-4E75-8BC6-A5F78AB549B2}.Release|Any CPU.Build.0 = Release|Any CPU
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE
@@ -50,6 +56,7 @@ Global
 		{903CD13A-D54B-4CEC-A55F-E22AE3D93B3B} = {A1893BD1-333D-4DFE-A0F0-DDBB2FE526E0}
 		{37EADF84-5E41-4224-A194-1E3299DCD0B8} = {E30F638E-BBBE-4AD1-93CE-48CC69CFEFE1}
 		{65357FBC-9BC4-466D-B621-1C3A19BC2A78} = {F2407211-6043-439C-8E06-3641634332E7}
+		{6D5986FF-EECD-4E75-8BC6-A5F78AB549B2} = {E30F638E-BBBE-4AD1-93CE-48CC69CFEFE1}
 	EndGlobalSection
 	GlobalSection(ExtensibilityGlobals) = postSolution
 		SolutionGuid = {811E61C5-3871-4633-AFAE-B35B619C8A10}

serilog-extensions-logging.sln.DotSettings

@@ -1,7 +1,11 @@
 <wpf:ResourceDictionary xml:space="preserve" xmlns:x="http://schemas.microsoft.com/winfx/2006/xaml" xmlns:s="clr-namespace:System;assembly=mscorlib" xmlns:ss="urn:shemas-jetbrains-com:settings-storage-xaml" xmlns:wpf="http://schemas.microsoft.com/winfx/2006/xaml/presentation">
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=destructure/@EntryIndexedValue">True</s:Boolean>
+	<s:Boolean x:Key="/Default/UserDictionary/Words/=destructured/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=Destructurer/@EntryIndexedValue">True</s:Boolean>
+	<s:Boolean x:Key="/Default/UserDictionary/Words/=Destructures/@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/=Loggable/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=Nonscalar/@EntryIndexedValue">True</s:Boolean>
-	<s:Boolean x:Key="/Default/UserDictionary/Words/=Serilog/@EntryIndexedValue">True</s:Boolean></wpf:ResourceDictionary>
+	<s:Boolean x:Key="/Default/UserDictionary/Words/=Serilog/@EntryIndexedValue">True</s:Boolean>
+	<s:Boolean x:Key="/Default/UserDictionary/Words/=sobj/@EntryIndexedValue">True</s:Boolean></wpf:ResourceDictionary>

src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs

@@ -4,6 +4,7 @@
 using Microsoft.Extensions.Logging;
 using System;
 using System.Collections.Generic;
+using System.Linq;
 using Serilog.Core;
 using Serilog.Events;
 using FrameworkLogger = Microsoft.Extensions.Logging.ILogger;
@@ -17,15 +18,19 @@ class SerilogLogger : FrameworkLogger
         readonly SerilogLoggerProvider _provider;
         readonly ILogger _logger;
 
-        static readonly MessageTemplateParser _messageTemplateParser = new MessageTemplateParser();
+        static readonly MessageTemplateParser MessageTemplateParser = new MessageTemplateParser();
+
+        // It's rare to see large event ids, as they are category-specific
+        static readonly LogEventProperty[] LowEventIdValues = Enumerable.Range(0, 48)
+            .Select(n => new LogEventProperty("Id", new ScalarValue(n)))
+            .ToArray();
 
         public SerilogLogger(
             SerilogLoggerProvider provider,
             ILogger logger = null,
             string name = null)
         {
-            if (provider == null) throw new ArgumentNullException(nameof(provider));
-            _provider = provider;
+            _provider = provider ?? throw new ArgumentNullException(nameof(provider));
             _logger = logger;
 
             // If a logger was passed, the provider has already added itself as an enricher
@@ -60,25 +65,22 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
 
             var properties = new List<LogEventProperty>();
 
-            var structure = state as IEnumerable<KeyValuePair<string, object>>;
-            if (structure != null)
+            if (state is IEnumerable<KeyValuePair<string, object>> structure)
             {
                 foreach (var property in structure)
                 {
-                    if (property.Key == SerilogLoggerProvider.OriginalFormatPropertyName && property.Value is string)
+                    if (property.Key == SerilogLoggerProvider.OriginalFormatPropertyName && property.Value is string value)
                     {
-                        messageTemplate = (string)property.Value;
+                        messageTemplate = value;
                     }
                     else if (property.Key.StartsWith("@"))
                     {
-                        LogEventProperty destructured;
-                        if (logger.BindProperty(property.Key.Substring(1), property.Value, true, out destructured))
+                        if (logger.BindProperty(property.Key.Substring(1), property.Value, true, out var destructured))
                             properties.Add(destructured);
                     }
                     else
                     {
-                        LogEventProperty bound;
-                        if (logger.BindProperty(property.Key, property.Value, false, out bound))
+                        if (logger.BindProperty(property.Key, property.Value, false, out var bound))
                             properties.Add(bound);
                     }                    
                 }
@@ -89,8 +91,7 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
                 if (messageTemplate == null && !stateTypeInfo.IsGenericType)
                 {
                     messageTemplate = "{" + stateType.Name + ":l}";
-                    LogEventProperty stateTypeProperty;
-                    if (logger.BindProperty(stateType.Name, AsLoggableValue(state, formatter), false, out stateTypeProperty))
+                    if (logger.BindProperty(stateType.Name, AsLoggableValue(state, formatter), false, out var stateTypeProperty))
                         properties.Add(stateTypeProperty);
                 }
             }
@@ -111,16 +112,15 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
 
                 if (propertyName != null)
                 {
-                    LogEventProperty property;
-                    if (logger.BindProperty(propertyName, AsLoggableValue(state, formatter), false, out property))
+                    if (logger.BindProperty(propertyName, AsLoggableValue(state, formatter), false, out var property))
                         properties.Add(property);
                 }
             }
 
             if (eventId.Id != 0 || eventId.Name != null)
                 properties.Add(CreateEventIdProperty(eventId));
 
-            var parsedTemplate = _messageTemplateParser.Parse(messageTemplate ?? "");
+            var parsedTemplate = MessageTemplateParser.Parse(messageTemplate ?? "");
             var evt = new LogEvent(DateTimeOffset.Now, level, exception, parsedTemplate, properties);
             logger.Write(evt);
         }
@@ -133,13 +133,17 @@ static object AsLoggableValue<TState>(TState state, Func<TState, Exception, stri
             return sobj;
         }
 
-        static LogEventProperty CreateEventIdProperty(EventId eventId)
+        internal static LogEventProperty CreateEventIdProperty(EventId eventId)
         {
             var properties = new List<LogEventProperty>(2);
 
             if (eventId.Id != 0)
             {
-                properties.Add(new LogEventProperty("Id", new ScalarValue(eventId.Id)));
+                if (eventId.Id < LowEventIdValues.Length)
+                    // Avoid some allocations
+                    properties.Add(LowEventIdValues[eventId.Id]);
+                else
+                    properties.Add(new LogEventProperty("Id", new ScalarValue(eventId.Id)));
             }
 
             if (eventId.Name != null)

test/Serilog.Extensions.Logging.Benchmarks/LogEventConstructionBenchmark.cs

@@ -0,0 +1,103 @@
+// Copyright 2019 Serilog Contributors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+using System;
+using BenchmarkDotNet.Attributes;
+using BenchmarkDotNet.Running;
+using Microsoft.Extensions.Logging;
+using IMelLogger = Microsoft.Extensions.Logging.ILogger;
+using Serilog.Events;
+using Serilog.Extensions.Logging.Benchmarks.Support;
+using Xunit;
+
+namespace Serilog.Extensions.Logging.Benchmarks
+{
+    [MemoryDiagnoser]
+    public class LogEventConstructionBenchmark
+    {
+        readonly IMelLogger _melLogger;
+        readonly ILogger _serilogContextualLogger;
+        readonly CapturingSink _sink;
+        const int LowId = 10, HighId = 101;
+        const string Template = "This is an event";
+
+        public LogEventConstructionBenchmark()
+        {
+            _sink = new CapturingSink();
+            var underlyingLogger = new LoggerConfiguration().WriteTo.Sink(_sink).CreateLogger();
+            _serilogContextualLogger = underlyingLogger.ForContext<LogEventConstructionBenchmark>();
+            _melLogger = new SerilogLoggerProvider(underlyingLogger).CreateLogger(GetType().FullName);
+        }
+
+        static void VerifyEventId(LogEvent evt, int? expectedId)
+        {
+            if (evt == null) throw new ArgumentNullException(nameof(evt));
+            if (expectedId == null)
+            {
+                Assert.False(evt.Properties.TryGetValue("EventId", out _));
+            }
+            else
+            {
+                Assert.True(evt.Properties.TryGetValue("EventId", out var eventIdValue));
+                var structure = Assert.IsType<StructureValue>(eventIdValue);
+                var idValue = Assert.Single(structure.Properties, p => p.Name == "Id")?.Value;
+                var scalar = Assert.IsType<ScalarValue>(idValue);
+                Assert.Equal(expectedId.Value, scalar.Value);
+            }
+        }
+
+        [Fact]
+        public void Verify()
+        {
+            VerifyEventId(Native(), null);
+            VerifyEventId(NoId(), null);
+            VerifyEventId(LowNumbered(), LowId);
+            VerifyEventId(HighNumbered(), HighId);
+        }
+
+        [Fact]
+        public void Benchmark()
+        {
+            BenchmarkRunner.Run<LogEventConstructionBenchmark>();
+        }
+
+        [Benchmark(Baseline = true)]
+        public LogEvent Native()
+        {
+            _serilogContextualLogger.Information(Template);
+            return _sink.Collect();
+        }
+
+        [Benchmark]
+        public LogEvent NoId()
+        {
+            _melLogger.LogInformation(Template);
+            return _sink.Collect();
+        }
+
+        [Benchmark]
+        public LogEvent LowNumbered()
+        {
+            _melLogger.LogInformation(LowId, Template);
+            return _sink.Collect();
+        }
+
+        [Benchmark]
+        public LogEvent HighNumbered()
+        {
+            _melLogger.LogInformation(HighId, Template);
+            return _sink.Collect();
+        }
+    }
+}

test/Serilog.Extensions.Logging.Benchmarks/Serilog.Extensions.Logging.Benchmarks.csproj

@@ -0,0 +1,26 @@
+<Project Sdk="Microsoft.NET.Sdk">
+
+  <PropertyGroup>
+    <TargetFrameworks>netcoreapp2.2</TargetFrameworks>
+    <GenerateRuntimeConfigurationFiles>true</GenerateRuntimeConfigurationFiles>
+  </PropertyGroup>
+
+  <ItemGroup>
+    <ProjectReference Include="..\..\src\Serilog.Extensions.Logging\Serilog.Extensions.Logging.csproj" />
+  </ItemGroup>
+
+  <ItemGroup>
+    <PackageReference Include="Microsoft.NET.Test.Sdk" Version="16.1.1" />
+    <PackageReference Include="xunit.runner.visualstudio" Version="2.4.1">
+      <PrivateAssets>all</PrivateAssets>
+      <IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
+    </PackageReference>
+    <PackageReference Include="xunit" Version="2.4.1" />
+    <PackageReference Include="BenchmarkDotNet" Version="0.11.5" />
+  </ItemGroup>
+
+  <ItemGroup>
+    <Service Include="{82a7f48d-3b50-4b1e-b82e-3ada8210c358}" />
+  </ItemGroup>
+
+</Project>

test/Serilog.Extensions.Logging.Benchmarks/Support/CapturingSink.cs

@@ -0,0 +1,36 @@
+// Copyright 2019 Serilog Contributors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+using Serilog.Core;
+using Serilog.Events;
+
+namespace Serilog.Extensions.Logging.Benchmarks.Support
+{
+    class CapturingSink : ILogEventSink
+    {
+        LogEvent _emitted;
+
+        public void Emit(LogEvent logEvent)
+        {
+            _emitted = logEvent;
+        }
+
+        public LogEvent Collect()
+        {
+            var collected = _emitted;
+            _emitted = null;
+            return collected;
+        }
+    }
+}