From 94af52a135a95cadd14e830820f2c5b70f7e3dc6 Mon Sep 17 00:00:00 2001 From: Lucas Trzesniewski Date: Sun, 7 Jan 2024 15:25:59 +0100 Subject: [PATCH] Add ZLogger to latency benchmarks --- .../LatencyTests/LatencyBenchmarks.cs | 84 ++++++++++++++++--- .../ZeroLog.Benchmarks.csproj | 1 + src/ZeroLog.sln.DotSettings | 1 + 3 files changed, 76 insertions(+), 10 deletions(-) diff --git a/src/ZeroLog.Benchmarks/LatencyTests/LatencyBenchmarks.cs b/src/ZeroLog.Benchmarks/LatencyTests/LatencyBenchmarks.cs index f6f2ea6..4feb70d 100644 --- a/src/ZeroLog.Benchmarks/LatencyTests/LatencyBenchmarks.cs +++ b/src/ZeroLog.Benchmarks/LatencyTests/LatencyBenchmarks.cs @@ -1,17 +1,25 @@ using System; +using System.IO; using BenchmarkDotNet.Attributes; +using JetBrains.Annotations; +using Microsoft.Extensions.Logging; using Serilog.Events; +using ZeroLog; using ZeroLog.Benchmarks.Tools; using ZeroLog.Configuration; using ZeroLog.Tests; +using ZLogger; -namespace ZeroLog.Benchmarks.LatencyTests; +// ReSharper disable once CheckNamespace +namespace Benchmarks; [MemoryDiagnoser] [AllStatisticsColumn] -[SimpleJob(iterationCount: 100, invocationCount: 8 * 1024)] -public class LatencyBenchmarks +[SimpleJob(iterationCount: 64, invocationCount: 128)] +public partial class LatencyBenchmarks { + private const int _operationCount = 8 * 1024; + private static readonly string _text = "dude"; private static readonly DateTime _date = DateTime.UtcNow; private static readonly int _number = 42; @@ -20,17 +28,22 @@ public class LatencyBenchmarks private TestAppender _zeroLogTestAppender; private Log _zeroLogLogger; + // ZLogger + private ILoggerFactory _zLoggerFactory; + private ILogger _zLoggerLogger; + // Serilog private SerilogTestSink _serilogTestSink; private Serilog.Core.Logger _serilogLogger; [ParamsAllValues] - public bool Enabled { get; set; } + public bool Enabled { get; [UsedImplicitly] set; } [GlobalSetup] public void Setup() { SetupZeroLog(); + SetupZLogger(); SetupSerilog(); } @@ -38,6 +51,7 @@ public void Setup() public void Cleanup() { TearDownZeroLog(); + TearDownZLogger(); TearDownSerilog(); } @@ -51,29 +65,73 @@ private void SetupZeroLog() LogManager.Initialize(new ZeroLogConfiguration { - LogMessagePoolSize = 32 * 1024, + LogMessagePoolSize = _operationCount, RootLogger = { - Level = Enabled ? LogLevel.Info : LogLevel.Warn, + Level = Enabled ? global::ZeroLog.LogLevel.Info : global::ZeroLog.LogLevel.Warn, LogMessagePoolExhaustionStrategy = LogMessagePoolExhaustionStrategy.WaitUntilAvailable, Appenders = { _zeroLogTestAppender } } }); _zeroLogLogger = LogManager.GetLogger(nameof(ZeroLog)); + + if (_zeroLogLogger.IsInfoEnabled != Enabled) + throw new InvalidOperationException(); } private void TearDownZeroLog() => LogManager.Shutdown(); - [Benchmark(Baseline = true)] + [Benchmark(Baseline = true, OperationsPerInvoke = _operationCount)] public void ZeroLog() - => _zeroLogLogger.Info($"Hi {_text} ! It's {_date:HH:mm:ss}, and the message is #{_number}"); + { + for (var i = 0; i < _operationCount; ++i) + _zeroLogLogger.Info($"Hi {_text}! It's {_date:HH:mm:ss}, and the message is #{_number}"); + } [IterationCleanup(Target = nameof(ZeroLog))] public void CleanupZeroLogIteration() => LogManager.Flush(); + // + // ZLogger + // + + private void SetupZLogger() + { + _zLoggerFactory = LoggerFactory.Create(logging => + { + logging.AddZLoggerStream(Stream.Null); + logging.SetMinimumLevel(Enabled ? Microsoft.Extensions.Logging.LogLevel.Information : Microsoft.Extensions.Logging.LogLevel.Warning); + }); + + _zLoggerLogger = _zLoggerFactory.CreateLogger(nameof(ZLogger)); + + if (_zLoggerLogger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Information) != Enabled) + throw new InvalidOperationException(); + } + + private void TearDownZLogger() + => _zLoggerFactory.Dispose(); + + [Benchmark(OperationsPerInvoke = _operationCount)] + public void ZLogger() + { + for (var i = 0; i < _operationCount; ++i) + _zLoggerLogger.ZLogInformation($"Hi {_text}! It's {_date:HH:mm:ss}, and the message is #{_number}"); + } + + [Benchmark(OperationsPerInvoke = _operationCount)] + public void ZLoggerGenerated() + { + for (var i = 0; i < _operationCount; ++i) + ZLoggerGenerated(_zLoggerLogger, _text, _date, _number); + } + + [ZLoggerMessage(Microsoft.Extensions.Logging.LogLevel.Information, "Hi {name}! It's {hour:HH:mm:ss}, and the message is #{number}")] + private static partial void ZLoggerGenerated(ILogger logger, string name, DateTime hour, int number); + // // Serilog // @@ -86,12 +144,18 @@ private void SetupSerilog() .WriteTo.Sink(_serilogTestSink) .MinimumLevel.Is(Enabled ? LogEventLevel.Information : LogEventLevel.Warning) .CreateLogger(); + + if (_serilogLogger.IsEnabled(LogEventLevel.Information) != Enabled) + throw new InvalidOperationException(); } private void TearDownSerilog() => _serilogLogger.Dispose(); - [Benchmark] + [Benchmark(OperationsPerInvoke = _operationCount)] public void Serilog() - => _serilogLogger.Information("Hi {name} ! It's {hour:HH:mm:ss}, and the message is #{number}", _text, _date, _number); + { + for (var i = 0; i < _operationCount; ++i) + _serilogLogger.Information("Hi {name}! It's {hour:HH:mm:ss}, and the message is #{number}", _text, _date, _number); + } } diff --git a/src/ZeroLog.Benchmarks/ZeroLog.Benchmarks.csproj b/src/ZeroLog.Benchmarks/ZeroLog.Benchmarks.csproj index 385ea4c..7d8764a 100644 --- a/src/ZeroLog.Benchmarks/ZeroLog.Benchmarks.csproj +++ b/src/ZeroLog.Benchmarks/ZeroLog.Benchmarks.csproj @@ -22,6 +22,7 @@ + diff --git a/src/ZeroLog.sln.DotSettings b/src/ZeroLog.sln.DotSettings index 25b252d..081bd3d 100644 --- a/src/ZeroLog.sln.DotSettings +++ b/src/ZeroLog.sln.DotSettings @@ -15,6 +15,7 @@ NEVER False True + True <Policy Inspect="True" Prefix="" Suffix="" Style="AaBb" /> <Policy Inspect="True" Prefix="_" Suffix="" Style="aaBb" /> <Policy Inspect="True" Prefix="_" Suffix="" Style="aaBb" />