Benchmarks: Add Serilog

Abc-Arbitrage · Feb 7, 2023 · 722bbac · 722bbac
1 parent 0fcd97c
commit 722bbac
Show file tree

Hide file tree

Showing 9 changed files with 143 additions and 12 deletions.
diff --git a/.gitignore b/.gitignore
@@ -15,4 +15,5 @@ Thumbs.db
 *.binlog
 *.orig
 
+BenchmarkDotNet.Artifacts/
 *.received.*
diff --git a/README.md b/README.md
@@ -11,7 +11,7 @@ Since ZeroLog does not aim to replace any existing logging libraries in any kind
 
 The project is production ready and you can [get it via NuGet](https://www.nuget.org/packages/ZeroLog) if you want to give it a try.
 
-**ZeroLog v2 requires .NET 6 and C# 10.** If your application targets an earlier .NET version, you can use [ZeroLog v1](https://github.com/Abc-Arbitrage/ZeroLog/tree/v1). Note that a .NET Standard 2.0 target is provided with a limited API surface for use by libraries, but it still requires the main application to target .NET 6 or later.
+**ZeroLog v2 requires .NET 6 and C# 10 or later.** If your application targets an earlier .NET version, you can use [ZeroLog v1](https://github.com/Abc-Arbitrage/ZeroLog/tree/v1). Note that a .NET Standard 2.0 target is provided with a limited API surface for use by libraries, but it still requires the main application to target .NET 6 or later.
 
 
 ## Internal Design

diff --git a/src/ZeroLog.Benchmarks/LatencyTests/SerilogMultiProducer.cs b/src/ZeroLog.Benchmarks/LatencyTests/SerilogMultiProducer.cs
@@ -0,0 +1,36 @@
+using System;
+using HdrHistogram;
+using ZeroLog.Benchmarks.Tools;
+using ZeroLog.Configuration;
+using ZeroLog.Tests;
+
+namespace ZeroLog.Benchmarks.LatencyTests;
+
+public class SerilogMultiProducer
+{
+    public SimpleLatencyBenchmarkResult Bench(int warmingMessageCount, int totalMessageCount, int producingThreadCount)
+    {
+        var sink = new SerilogTestSink(false);
+
+        var logger = new Serilog.LoggerConfiguration()
+                     .WriteTo.Sink(sink)
+                     .CreateLogger();
+
+        var signal = sink.SetMessageCountTarget(warmingMessageCount + totalMessageCount);
+
+        var produce = new Func<HistogramBase>(() =>
+        {
+            var warmingMessageByProducer = warmingMessageCount / producingThreadCount;
+            int[] counter = { 0 };
+            var warmingResult = SimpleLatencyBenchmark.Bench(() => logger.Information("Hi {name} ! It's {date:HH:mm:ss}, and the message is #{number}", "dude", DateTime.UtcNow, counter[0]++), warmingMessageByProducer);
+
+            var messageByProducer = totalMessageCount / producingThreadCount;
+            counter[0] = 0;
+            return SimpleLatencyBenchmark.Bench(() => logger.Information("Hi {name} ! It's {date:HH:mm:ss}, and the message is #{number}", "dude", DateTime.UtcNow, counter[0]++), messageByProducer);
+        });
+
+        var result = SimpleLatencyBenchmark.RunBench(producingThreadCount, produce, signal);
+
+        return result;
+    }
+}
diff --git a/src/ZeroLog.Benchmarks/Program.cs b/src/ZeroLog.Benchmarks/Program.cs
@@ -27,12 +27,16 @@ private static void LatencyMultiProducer(int threadCount, int warmupMessageCount
         var nlogSync = new NLogSyncMultiProducer().Bench(warmupMessageCount, messageCount, threadCount);
         var nlogAsync = new NLogAsyncMultiProducer().Bench(queueSize, warmupMessageCount, messageCount, threadCount);
         var log4net = new Log4NetMultiProducer().Bench(warmupMessageCount, messageCount, threadCount);
-
-        SimpleLatencyBenchmark.PrintSummary($"{threadCount} producers, {messageCount:N0} total log events (queue size={queueSize:N0}) - unit is *us*",
-                                            ("ZeroLog", zeroLog),
-                                            ("NLogSync", nlogSync),
-                                            ("NLogAsync", nlogAsync),
-                                            ("Log4net", log4net));
+        var serilog = new SerilogMultiProducer().Bench(warmupMessageCount, messageCount, threadCount);
+
+        SimpleLatencyBenchmark.PrintSummary(
+            $"{threadCount} producers, {messageCount:N0} total log events (queue size={queueSize:N0}) - unit is *us*",
+            ("ZeroLog", zeroLog),
+            ("NLogSync", nlogSync),
+            ("NLogAsync", nlogAsync),
+            ("Log4net", log4net),
+            ("Serilog", serilog)
+        );
     }
 
     public static void Main()

diff --git a/src/ZeroLog.Benchmarks/ThroughputTests/ThroughputBenchmarks.cs b/src/ZeroLog.Benchmarks/ThroughputTests/ThroughputBenchmarks.cs
@@ -7,12 +7,14 @@
 using NLog;
 using NLog.Config;
 using NLog.Targets.Wrappers;
+using ZeroLog.Benchmarks.Tools;
 using ZeroLog.Configuration;
 
 namespace ZeroLog.Benchmarks.ThroughputTests;
 
 [MemoryDiagnoser]
-[SimpleJob(RunStrategy.ColdStart, iterationCount: 1000, invocationCount: 1, baseline: true)]
+[AllStatisticsColumn]
+[SimpleJob(RunStrategy.ColdStart, iterationCount: 100, invocationCount: 1, baseline: true)]
 public class ThroughputBenchmarks
 {
     [Params(4)]
@@ -22,6 +24,7 @@ public class ThroughputBenchmarks
     public int TotalMessageCount;
 
     [Params(8192)]
+    //[Params(4 * 50_000)]
     public int QueueSize;
 
     // ZeroLog
@@ -38,12 +41,17 @@ public class ThroughputBenchmarks
     private NLogTestTarget _nLogAsyncTestTarget;
     private Logger _nLogAsyncLogger;
 
+    // Serilog
+    private SerilogTestSink _serilogTestSink;
+    private Serilog.Core.Logger _serilogLogger;
+
     [GlobalSetup]
     public void Setup()
     {
         SetupZeroLog();
         SetupLog4Net();
         SetupLogNLog();
+        SetupSerilog();
     }
 
     [GlobalCleanup]
@@ -52,6 +60,7 @@ public void Cleanup()
         TearDownZeroLog();
         TearDownLog4Net();
         TearDownNLog();
+        TearDownSerilog();
     }
 
     //
@@ -208,4 +217,39 @@ public void NLogAsync()
 
         signal.Wait(TimeSpan.FromSeconds(30));
     }
+
+    //
+    // Serilog
+    //
+
+    private void SetupSerilog()
+    {
+        _serilogTestSink = new SerilogTestSink(false);
+
+        _serilogLogger = new Serilog.LoggerConfiguration()
+                         .WriteTo.Sink(_serilogTestSink)
+                         .CreateLogger();
+    }
+
+    private void TearDownSerilog()
+    {
+        _serilogLogger.Dispose();
+    }
+
+    [Benchmark]
+    public void Serilog()
+    {
+        var signal = _serilogTestSink.SetMessageCountTarget(TotalMessageCount);
+
+        var produce = new Action(() =>
+        {
+            for (var i = 0; i < TotalMessageCount / ProducingThreadCount; i++)
+                _serilogLogger.Information("Hi {name} ! It's {hour:HH:mm:ss}, and the message is #{number}", "dude", DateTime.UtcNow, i);
+        });
+
+        for (var i = 0; i < ProducingThreadCount; i++)
+            Task.Factory.StartNew(produce, TaskCreationOptions.LongRunning);
+
+        signal.Wait(TimeSpan.FromSeconds(30));
+    }
 }
diff --git a/src/ZeroLog.Benchmarks/Tools/SerilogTestSink.cs b/src/ZeroLog.Benchmarks/Tools/SerilogTestSink.cs
@@ -0,0 +1,45 @@
+using System;
+using System.Collections.Generic;
+using System.Threading;
+using Serilog.Core;
+using Serilog.Events;
+
+namespace ZeroLog.Benchmarks.Tools;
+
+public class SerilogTestSink : ILogEventSink
+{
+    private readonly bool _captureLoggedMessages;
+    private readonly object _lock = new();
+    private int _messageCount;
+    private ManualResetEventSlim _signal;
+    private int _messageCountTarget;
+
+    public List<string> LoggedMessages { get; } = new();
+
+    public SerilogTestSink(bool captureLoggedMessages)
+    {
+        _captureLoggedMessages = captureLoggedMessages;
+    }
+
+    public ManualResetEventSlim SetMessageCountTarget(int expectedMessageCount)
+    {
+        _signal = new ManualResetEventSlim(false);
+        _messageCount = 0;
+        _messageCountTarget = expectedMessageCount;
+        return _signal;
+    }
+
+    public void Emit(LogEvent logEvent)
+    {
+        var formatted = logEvent.RenderMessage();
+
+        lock (_lock)
+        {
+            if (_captureLoggedMessages)
+                LoggedMessages.Add(formatted);
+
+            if (++_messageCount == _messageCountTarget)
+                _signal.Set();
+        }
+    }
+}
diff --git a/src/ZeroLog.Benchmarks/ZeroLog.Benchmarks.csproj b/src/ZeroLog.Benchmarks/ZeroLog.Benchmarks.csproj
@@ -18,6 +18,7 @@
     <PackageReference Include="InlineIL.Fody" Version="1.7.4" PrivateAssets="all" />
     <PackageReference Include="log4net" Version="2.0.15" />
     <PackageReference Include="NLog" Version="5.1.1" />
+    <PackageReference Include="Serilog" Version="2.12.0" />
     <PackageReference Include="System.Net.Sockets" Version="4.3.0" />
   </ItemGroup>
 

diff --git a/src/ZeroLog.Tests.NetStandard/ZeroLog.Tests.NetStandard.csproj b/src/ZeroLog.Tests.NetStandard/ZeroLog.Tests.NetStandard.csproj
@@ -11,8 +11,8 @@
     <PackageReference Include="Microsoft.NET.Test.Sdk" Version="17.4.1" />
     <PackageReference Include="NUnit" Version="3.13.3" />
     <PackageReference Include="NUnit3TestAdapter" Version="4.3.1" />
-    <PackageReference Include="Verify.NUnit" Version="19.8.3" />
-    <PackageReference Include="Verify.DiffPlex" Version="2.1.0" />
+    <PackageReference Include="Verify.NUnit" Version="19.9.2" />
+    <PackageReference Include="Verify.DiffPlex" Version="2.2.0" />
     <PackageReference Include="PublicApiGenerator" Version="10.3.0" />
   </ItemGroup>
 

diff --git a/src/ZeroLog.Tests/ZeroLog.Tests.csproj b/src/ZeroLog.Tests/ZeroLog.Tests.csproj
@@ -13,8 +13,8 @@
     <PackageReference Include="NUnit" Version="3.13.3" />
     <PackageReference Include="NUnit3TestAdapter" Version="4.3.1" />
     <PackageReference Include="MarkdownSnippets.MsBuild" Version="24.5.1" />
-    <PackageReference Include="Verify.NUnit" Version="19.8.3" />
-    <PackageReference Include="Verify.DiffPlex" Version="2.1.0" />
+    <PackageReference Include="Verify.NUnit" Version="19.9.2" />
+    <PackageReference Include="Verify.DiffPlex" Version="2.2.0" />
     <PackageReference Include="PublicApiGenerator" Version="10.3.0" />
   </ItemGroup>