diff --git a/serilog-extensions-logging.sln b/serilog-extensions-logging.sln index 80abb55..c53414c 100644 --- a/serilog-extensions-logging.sln +++ b/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} diff --git a/serilog-extensions-logging.sln.DotSettings b/serilog-extensions-logging.sln.DotSettings index c6bac2f..4009815 100644 --- a/serilog-extensions-logging.sln.DotSettings +++ b/serilog-extensions-logging.sln.DotSettings @@ -1,7 +1,11 @@  True + True True + True True True + True True - True \ No newline at end of file + True + True \ No newline at end of file diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs index 6f91fa1..89b9f93 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs +++ b/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(LogLevel logLevel, EventId eventId, TState state, Except var properties = new List(); - var structure = state as IEnumerable>; - if (structure != null) + if (state is IEnumerable> 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(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,8 +112,7 @@ public void Log(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); } } @@ -120,7 +120,7 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except 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 state, Func(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) diff --git a/test/Serilog.Extensions.Logging.Benchmarks/LogEventConstructionBenchmark.cs b/test/Serilog.Extensions.Logging.Benchmarks/LogEventConstructionBenchmark.cs new file mode 100644 index 0000000..51cae2e --- /dev/null +++ b/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(); + _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(eventIdValue); + var idValue = Assert.Single(structure.Properties, p => p.Name == "Id")?.Value; + var scalar = Assert.IsType(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(); + } + + [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(); + } + } +} diff --git a/test/Serilog.Extensions.Logging.Benchmarks/Serilog.Extensions.Logging.Benchmarks.csproj b/test/Serilog.Extensions.Logging.Benchmarks/Serilog.Extensions.Logging.Benchmarks.csproj new file mode 100644 index 0000000..7840f21 --- /dev/null +++ b/test/Serilog.Extensions.Logging.Benchmarks/Serilog.Extensions.Logging.Benchmarks.csproj @@ -0,0 +1,26 @@ + + + + netcoreapp2.2 + true + + + + + + + + + + all + runtime; build; native; contentfiles; analyzers; buildtransitive + + + + + + + + + + diff --git a/test/Serilog.Extensions.Logging.Benchmarks/Support/CapturingSink.cs b/test/Serilog.Extensions.Logging.Benchmarks/Support/CapturingSink.cs new file mode 100644 index 0000000..3913561 --- /dev/null +++ b/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; + } + } +} diff --git a/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs b/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs index a83ca0c..d2d5bac 100644 --- a/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs +++ b/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs @@ -16,56 +16,28 @@ namespace Serilog.Extensions.Logging.Tests { public class SerilogLoggerTest { - private const string Name = "test"; - private const string TestMessage = "This is a test"; + const string Name = "test"; + const string TestMessage = "This is a test"; - private Tuple SetUp(LogLevel logLevel) + static Tuple SetUp(LogLevel logLevel) { var sink = new SerilogSink(); - var config = new LoggerConfiguration() - .WriteTo.Sink(sink); + var serilogLogger = new LoggerConfiguration() + .WriteTo.Sink(sink) + .MinimumLevel.Is(LevelConvert.ToSerilogLevel(logLevel)) + .CreateLogger(); - SetMinLevel(config, logLevel); - - var provider = new SerilogLoggerProvider(config.CreateLogger()); + var provider = new SerilogLoggerProvider(serilogLogger); var logger = (SerilogLogger)provider.CreateLogger(Name); return new Tuple(logger, sink); } - private void SetMinLevel(LoggerConfiguration serilog, LogLevel logLevel) - { - serilog.MinimumLevel.Is(MapLevel(logLevel)); - } - - private LogEventLevel MapLevel(LogLevel logLevel) - { - switch (logLevel) - { - case LogLevel.Trace: - return LogEventLevel.Verbose; - case LogLevel.Debug: - return LogEventLevel.Debug; - case LogLevel.Information: - return LogEventLevel.Information; - case LogLevel.Warning: - return LogEventLevel.Warning; - case LogLevel.Error: - return LogEventLevel.Error; - case LogLevel.Critical: - return LogEventLevel.Fatal; - default: - return LogEventLevel.Verbose; - } - } - [Fact] public void LogsWhenNullFilterGiven() { - var t = SetUp(LogLevel.Trace); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(LogLevel.Trace); logger.Log(LogLevel.Information, 0, TestMessage, null, null); @@ -75,9 +47,7 @@ public void LogsWhenNullFilterGiven() [Fact] public void LogsCorrectLevel() { - var t = SetUp(LogLevel.Trace); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(LogLevel.Trace); logger.Log(LogLevel.Trace, 0, TestMessage, null, null); logger.Log(LogLevel.Debug, 0, TestMessage, null, null); @@ -134,9 +104,7 @@ public void LogsCorrectLevel() [InlineData(LogLevel.Critical, LogLevel.Critical, 1)] public void LogsWhenEnabled(LogLevel minLevel, LogLevel logLevel, int expected) { - var t = SetUp(minLevel); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(minLevel); logger.Log(logLevel, 0, TestMessage, null, null); @@ -146,9 +114,7 @@ public void LogsWhenEnabled(LogLevel minLevel, LogLevel logLevel, int expected) [Fact] public void LogsCorrectMessage() { - var t = SetUp(LogLevel.Trace); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(LogLevel.Trace); logger.Log(LogLevel.Information, 0, null, null, null); logger.Log(LogLevel.Information, 0, TestMessage, null, null); @@ -171,9 +137,7 @@ public void LogsCorrectMessage() [Fact] public void CarriesException() { - var t = SetUp(LogLevel.Trace); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(LogLevel.Trace); var exception = new Exception(); @@ -186,9 +150,7 @@ public void CarriesException() [Fact] public void SingleScopeProperty() { - var t = SetUp(LogLevel.Trace); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(LogLevel.Trace); using (logger.BeginScope(new FoodScope("pizza"))) { @@ -203,9 +165,7 @@ public void SingleScopeProperty() [Fact] public void NestedScopeSameProperty() { - var t = SetUp(LogLevel.Trace); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(LogLevel.Trace); using (logger.BeginScope(new FoodScope("avocado"))) { @@ -224,9 +184,7 @@ public void NestedScopeSameProperty() [Fact] public void NestedScopesDifferentProperties() { - var t = SetUp(LogLevel.Trace); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(LogLevel.Trace); using (logger.BeginScope(new FoodScope("spaghetti"))) { @@ -249,9 +207,7 @@ public void CarriesMessageTemplateProperties() var selfLog = new StringWriter(); SelfLog.Enable(selfLog); - var t = SetUp(LogLevel.Trace); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(LogLevel.Trace); logger.LogInformation("Hello, {Recipient}", "World"); @@ -266,11 +222,9 @@ public void CarriesMessageTemplateProperties() [Fact] public void CarriesEventIdIfNonzero() { - var t = SetUp(LogLevel.Trace); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(LogLevel.Trace); - int expected = 42; + const int expected = 42; logger.Log(LogLevel.Information, expected, "Test", null, null); @@ -302,9 +256,7 @@ public void WhenDisposeIsTrueProvidedLoggerIsDisposed() [Fact] public void BeginScopeDestructuresObjectsWhenDestructurerIsUsedInMessageTemplate() { - var t = SetUp(LogLevel.Trace); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(LogLevel.Trace); using (logger.BeginScope("{@Person}", new Person { FirstName = "John", LastName = "Smith" })) { @@ -324,9 +276,7 @@ public void BeginScopeDestructuresObjectsWhenDestructurerIsUsedInMessageTemplate [Fact] public void BeginScopeDestructuresObjectsWhenDestructurerIsUsedInDictionary() { - var t = SetUp(LogLevel.Trace); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(LogLevel.Trace); using (logger.BeginScope(new Dictionary {{ "@Person", new Person { FirstName = "John", LastName = "Smith" }}})) { @@ -346,9 +296,7 @@ public void BeginScopeDestructuresObjectsWhenDestructurerIsUsedInDictionary() [Fact] public void BeginScopeDoesNotModifyKeyWhenDestructurerIsNotUsedInMessageTemplate() { - var t = SetUp(LogLevel.Trace); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(LogLevel.Trace); using (logger.BeginScope("{FirstName}", "John")) { @@ -362,9 +310,7 @@ public void BeginScopeDoesNotModifyKeyWhenDestructurerIsNotUsedInMessageTemplate [Fact] public void BeginScopeDoesNotModifyKeyWhenDestructurerIsNotUsedInDictionary() { - var t = SetUp(LogLevel.Trace); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(LogLevel.Trace); using (logger.BeginScope(new Dictionary { { "FirstName", "John"}})) { @@ -378,9 +324,7 @@ public void BeginScopeDoesNotModifyKeyWhenDestructurerIsNotUsedInDictionary() [Fact] public void NamedScopesAreCaptured() { - var t = SetUp(LogLevel.Trace); - var logger = t.Item1; - var sink = t.Item2; + var (logger, sink) = SetUp(LogLevel.Trace); using (logger.BeginScope("Outer")) using (logger.BeginScope("Inner")) @@ -390,16 +334,15 @@ public void NamedScopesAreCaptured() Assert.Equal(1, sink.Writes.Count); - LogEventPropertyValue scopeValue; - Assert.True(sink.Writes[0].Properties.TryGetValue(SerilogLoggerProvider.ScopePropertyName, out scopeValue)); - - var items = (scopeValue as SequenceValue)?.Elements.Select(e => ((ScalarValue)e).Value).Cast().ToArray(); + Assert.True(sink.Writes[0].Properties.TryGetValue(SerilogLoggerProvider.ScopePropertyName, out var scopeValue)); + var sequence = Assert.IsType(scopeValue); + var items = sequence.Elements.Select(e => Assert.IsType(e).Value).Cast().ToArray(); Assert.Equal(2, items.Length); Assert.Equal("Outer", items[0]); Assert.Equal("Inner", items[1]); } - private class FoodScope : IEnumerable> + class FoodScope : IEnumerable> { readonly string _name; @@ -419,7 +362,7 @@ IEnumerator IEnumerable.GetEnumerator() } } - private class LuckyScope : IEnumerable> + class LuckyScope : IEnumerable> { readonly int _luckyNumber; @@ -439,10 +382,29 @@ IEnumerator IEnumerable.GetEnumerator() } } - private class Person + class Person { + // ReSharper disable once UnusedAutoPropertyAccessor.Local public string FirstName { get; set; } + + // ReSharper disable once UnusedAutoPropertyAccessor.Local public string LastName { get; set; } } + + [Theory] + [InlineData(1)] + [InlineData(10)] + [InlineData(48)] + [InlineData(100)] + public void LowAndHighNumberedEventIdsAreMapped(int id) + { + var orig = new EventId(id, "test"); + var mapped = SerilogLogger.CreateEventIdProperty(orig); + var value = Assert.IsType(mapped.Value); + Assert.Equal(2, value.Properties.Count); + var idValue = value.Properties.Single(p => p.Name == "Id").Value; + var scalar = Assert.IsType(idValue); + Assert.Equal(id, scalar.Value); + } } -} \ No newline at end of file +}