Skip to content

Commit

Permalink
Merge pull request #142 from nblumhardt/event-id-caching
Browse files Browse the repository at this point in the history
Cache low-numbered numeric event ids to reduce allocations
  • Loading branch information
adamchester authored Aug 20, 2019
2 parents e1a4780 + 40a2a2d commit 11c3c07
Show file tree
Hide file tree
Showing 7 changed files with 251 additions and 109 deletions.
11 changes: 9 additions & 2 deletions serilog-extensions-logging.sln
Original file line number Diff line number Diff line change
@@ -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
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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}
Expand Down
6 changes: 5 additions & 1 deletion serilog-extensions-logging.sln.DotSettings
Original file line number Diff line number Diff line change
@@ -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>
40 changes: 22 additions & 18 deletions src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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
Expand Down Expand Up @@ -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);
}
}
Expand All @@ -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);
}
}
Expand All @@ -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);
}
Expand All @@ -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)
Expand Down
Original file line number Diff line number Diff line change
@@ -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();
}
}
}
Original file line number Diff line number Diff line change
@@ -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>
Original file line number Diff line number Diff line change
@@ -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;
}
}
}
Loading

0 comments on commit 11c3c07

Please sign in to comment.