Benchmarks to compare performance against Microsoft Logging proposal ( …

…dotnet/designs#195 / https://github.com/geeknoid/LoggingGenerator )
Drizin · Apr 16, 2021 · 604950d · 604950d
1 parent 211f1b7
commit 604950d
Show file tree

Hide file tree

Showing 5 changed files with 157 additions and 0 deletions.
diff --git a/README.md b/README.md
@@ -136,6 +136,18 @@ logger.Information($"Processed order in { new { TimeMS = time}:000} ms.");
 //logger.Information("Processed order in {TimeMS:000}ms.", input, time);
 ```
 
+# Performance / Benchmarks 
+
+Some people mentioned that Microsoft is working on a [proposal](https://github.com/dotnet/designs/pull/195) for a [Logging Generator](https://github.com/geeknoid/LoggingGenerator) 
+which uses C# 9 source generators and which should convert decorated partial-methods into strongly-typed logging functions.
+
+There are benchmark tests [here](https://github.com/Drizin/InterpolatedLogging/tree/main/src/InterpolatedLogging.Microsoft.Extensions.Logging.Tests/BenchmarkTests.cs) comparing InterpolatedLogging with Microsoft code, 
+and the results show that the performance of both libraries is nearly identical, and frequently InterpolatedLogging is even faster! Test the results yourself! 
+
+![Benchmarks - Microsoft LoggingGenerator](src/InterpolatedLogging.Microsoft.Extensions.Logging.Tests/BenchmarkTests-Result.png)
+
+
+
 
 # Collaborate
 

diff --git a/...nterpolatedLogging.Microsoft.Extensions.Logging.Tests/BenchmarkTests-Result.png b/...nterpolatedLogging.Microsoft.Extensions.Logging.Tests/BenchmarkTests-Result.png
diff --git a/src/InterpolatedLogging.Microsoft.Extensions.Logging.Tests/BenchmarkTests.cs b/src/InterpolatedLogging.Microsoft.Extensions.Logging.Tests/BenchmarkTests.cs
@@ -0,0 +1,107 @@
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Console;
+using NUnit.Framework;
+using System;
+using System.Collections;
+using System.Collections.Generic;
+using System.Data;
+using System.Data.SqlClient;
+using System.Diagnostics;
+using System.Linq;
+using System.Reflection;
+using static InterpolatedLogging.NamedProperties;
+
+namespace InterpolatedLogging.Tests
+{
+    public class BenchmarkTests
+    {
+
+
+        [Test]
+        public void BenchmarkTest1()
+        {
+            System.Diagnostics.Debug.WriteLine($"---------");
+            int iteractions = 100000;
+
+            var fac = Microsoft.Extensions.Logging.LoggerFactory.Create((builder) => { builder.SetMinimumLevel(LogLevel.Debug).AddConsole(); });
+            var logger = new Microsoft.Extensions.Logging.Logger<int>(fac);
+
+            // Microsoft Logging Generator ( https://github.com/geeknoid/LoggingGenerator )
+            var sw = Stopwatch.StartNew();
+            for (int i = 0; i < iteractions; i++)
+            {
+                Log.CouldNotOpenSocket(logger, Environment.MachineName);
+            }
+            System.Diagnostics.Debug.WriteLine($"Microsoft Logging Generator (1 argument): {sw.ElapsedMilliseconds}ms");
+
+            // InterpolatedLogging
+            sw = Stopwatch.StartNew();
+            for (int i = 0; i < iteractions; i++)
+            {
+                logger.InterpolatedDebug($"Could not open socket to `{Environment.MachineName:hostName}`");
+            }
+            System.Diagnostics.Debug.WriteLine($"InterpolatedLogging (1 argument): {sw.ElapsedMilliseconds}ms");
+        }
+
+        [Test]
+        public void BenchmarkTest2()
+        {
+            System.Diagnostics.Debug.WriteLine($"---------");
+            int iteractions = 100000;
+
+            var fac = Microsoft.Extensions.Logging.LoggerFactory.Create((builder) => { builder.SetMinimumLevel(LogLevel.Debug).AddConsole(); });
+            var logger = new Microsoft.Extensions.Logging.Logger<int>(fac);
+
+            // Microsoft Logging Generator ( https://github.com/geeknoid/LoggingGenerator )
+            var sw = Stopwatch.StartNew();
+            for (int i = 0; i < iteractions; i++)
+            {
+                Log.FourArgumentsLog(logger, Environment.MachineName, DateTime.Now, 10, true);
+            }
+            System.Diagnostics.Debug.WriteLine($"Microsoft Logging Generator (4 arguments): {sw.ElapsedMilliseconds}ms");
+
+            // InterpolatedLogging
+            sw = Stopwatch.StartNew();
+            for (int i = 0; i < iteractions; i++)
+            {
+                logger.InterpolatedDebug($"Could not open socket to `{Environment.MachineName:hostName}` at {DateTime.Now:Timestamp} with amount {10m:Amount} - flag is {true:Flag}");
+            }
+            System.Diagnostics.Debug.WriteLine($"InterpolatedLogging (4 arguments): {sw.ElapsedMilliseconds}ms");
+        }
+
+
+
+    }
+
+    static partial class Log
+    {
+        [global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "1.0.0.0")]
+        private static readonly global::System.Action<global::Microsoft.Extensions.Logging.ILogger, string, global::System.Exception> __CouldNotOpenSocketCallback =
+            global::Microsoft.Extensions.Logging.LoggerMessage.Define<string>(global::Microsoft.Extensions.Logging.LogLevel.Critical, new global::Microsoft.Extensions.Logging.EventId(0, nameof(CouldNotOpenSocket)), "Could not open socket to `{hostName}`");
+
+        [global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "1.0.0.0")]
+        public static void CouldNotOpenSocket(Microsoft.Extensions.Logging.ILogger logger, string hostName)
+        {
+            if (logger.IsEnabled(global::Microsoft.Extensions.Logging.LogLevel.Critical))
+            {
+                __CouldNotOpenSocketCallback(logger, hostName, null);
+            }
+        }
+
+
+
+        [global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "1.0.0.0")]
+        private static readonly global::System.Action<global::Microsoft.Extensions.Logging.ILogger, string, DateTime, decimal, bool, global::System.Exception> _FourArgumentsCallback =
+            global::Microsoft.Extensions.Logging.LoggerMessage.Define<string, DateTime, decimal, bool>(global::Microsoft.Extensions.Logging.LogLevel.Critical, new global::Microsoft.Extensions.Logging.EventId(0, nameof(CouldNotOpenSocket)), "Could not open socket to `{hostName}` at {Timestamp} with amount {Amount} - flag is {Flag}");
+
+        [global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "1.0.0.0")]
+        public static void FourArgumentsLog(Microsoft.Extensions.Logging.ILogger logger, string hostName, DateTime now, decimal amount, bool flag)
+        {
+            if (logger.IsEnabled(global::Microsoft.Extensions.Logging.LogLevel.Critical))
+            {
+                _FourArgumentsCallback(logger, hostName, now, amount, flag, null);
+            }
+        }
+
+    }
+}
diff --git a/...ft.Extensions.Logging.Tests/InterpolatedLogging.Microsoft.Extensions.Logging.Tests.csproj b/...ft.Extensions.Logging.Tests/InterpolatedLogging.Microsoft.Extensions.Logging.Tests.csproj
@@ -0,0 +1,32 @@
+<Project Sdk="Microsoft.NET.Sdk">
+
+  <PropertyGroup>
+    <TargetFramework>netcoreapp2.1</TargetFramework>
+
+    <IsPackable>false</IsPackable>
+
+    <Company>Rick Drizin</Company>
+
+    <Copyright>Rick Drizin</Copyright>
+
+    <PackageLicenseExpression>MIT</PackageLicenseExpression>
+
+    <PackageProjectUrl>https://github.com/Drizin/InterpolatedLogging/</PackageProjectUrl>
+  </PropertyGroup>
+
+  <ItemGroup>
+    <PackageReference Include="Microsoft.CSharp" Version="4.7.0" />
+    <PackageReference Include="Microsoft.Extensions.Logging" Version="6.0.0-preview.1.21102.12" />
+    <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="5.0.0" />
+    <PackageReference Include="Npgsql" Version="4.1.4" />
+    <PackageReference Include="nunit" Version="3.10.1" />
+    <PackageReference Include="NUnit3TestAdapter" Version="3.10.0" />
+    <PackageReference Include="Microsoft.NET.Test.Sdk" Version="15.8.0" />
+    <PackageReference Include="System.Data.SqlClient" Version="4.8.1" />
+  </ItemGroup>
+
+  <ItemGroup>
+    <ProjectReference Include="..\InterpolatedLogging.Microsoft.Extensions.Logging\InterpolatedLogging.Microsoft.Extensions.Logging.csproj" />
+  </ItemGroup>
+
+</Project>
diff --git a/src/InterpolatedLogging.sln b/src/InterpolatedLogging.sln
@@ -13,6 +13,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "InterpolatedLogging.Microso
 EndProject
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "InterpolatedLogging.NLog", "InterpolatedLogging.NLog\InterpolatedLogging.NLog.csproj", "{5874FE09-2F1F-48AA-990A-AA1214AA2BF5}"
 EndProject
+Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "InterpolatedLogging.Microsoft.Extensions.Logging.Tests", "InterpolatedLogging.Microsoft.Extensions.Logging.Tests\InterpolatedLogging.Microsoft.Extensions.Logging.Tests.csproj", "{D46D5A79-1BB2-4834-988C-FB94827A479D}"
+EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
 		Debug|Any CPU = Debug|Any CPU
@@ -39,6 +41,10 @@ Global
 		{5874FE09-2F1F-48AA-990A-AA1214AA2BF5}.Debug|Any CPU.Build.0 = Debug|Any CPU
 		{5874FE09-2F1F-48AA-990A-AA1214AA2BF5}.Release|Any CPU.ActiveCfg = Release|Any CPU
 		{5874FE09-2F1F-48AA-990A-AA1214AA2BF5}.Release|Any CPU.Build.0 = Release|Any CPU
+		{D46D5A79-1BB2-4834-988C-FB94827A479D}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{D46D5A79-1BB2-4834-988C-FB94827A479D}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{D46D5A79-1BB2-4834-988C-FB94827A479D}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{D46D5A79-1BB2-4834-988C-FB94827A479D}.Release|Any CPU.Build.0 = Release|Any CPU
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE