Improved Benchmark Tests

.github/workflows/perftests.yml

@@ -15,7 +15,7 @@ jobs:
         shell: pwsh
 
       - name: Run performance tests
-        run: ./RunPerfTests.ps1
+        run: ./RunPerfTests.ps1 -Filter ${{ secrets.PERF_TESTS_FILTER }}
         shell: pwsh
 
       - name: Upload perf test results artifact

.github/workflows/release.yml

@@ -36,7 +36,7 @@ jobs:
         shell: pwsh
 
       - name: Run performance tests
-        run: ./RunPerfTests.ps1
+        run: ./RunPerfTests.ps1 -Filter "*QuickBenchmarks*"
         shell: pwsh
 
       - name: Get last commit message
@@ -55,28 +55,30 @@ jobs:
 
           $nupkgFile = Get-ChildItem -Path "artifacts/$baseFileName*.nupkg" | Select-Object -First 1
           $snupkgFile = Get-ChildItem -Path "artifacts/$baseFileName*.snupkg" | Select-Object -First 1
-          $perfReportSinkFile = Get-ChildItem -Path "artifacts/perftests/Serilog.Sinks.MSSqlServer.PerformanceTests.SinkBenchmarks-report.csv" `
+          $perfReportSinkFile = Get-ChildItem -Path "artifacts/perftests/Serilog.Sinks.MSSqlServer.PerformanceTests.SinkQuickBenchmarks-report.csv" `
+            | Select-Object -First 1
+          $perfReportAuditSinkFile = Get-ChildItem -Path "artifacts/perftests/Serilog.Sinks.MSSqlServer.PerformanceTests.AuditSinkQuickBenchmarks-report.csv" `
             | Select-Object -First 1
 
           if (-not $nupkgFile) { Write-Error "nupkg file not found" ; exit 1 }
           if (-not $snupkgFile) { Write-Error "snupkg file not found" ; exit 1 }
           if (-not $perfReportSinkFile) { Write-Error "Benchmark report for sink file not found" ; exit 1 }
+          if (-not $perfReportAuditSinkFile) { Write-Error "Benchmark report for audit sink file not found" ; exit 1 }
 
           $nupkgFilePath = $nupkgFile.FullName -replace '\\', '/'
           $snupkgFilePath = $snupkgFile.FullName -replace '\\', '/'
           $perfReportSinkFilePath = $perfReportSinkFile.FullName -replace '\\', '/'
+          $perfReportAuditSinkFilePath = $perfReportAuditSinkFile.FullName -replace '\\', '/'
 
-          Write-Host "Uploading files: $nupkgFilePath, $snupkgFilePath $perfReportPipelineFilePath"
+          Write-Host "Uploading files: $nupkgFilePath, $snupkgFilePath $perfReportSinkFilePath $perfReportAuditSinkFilePath"
 
           gh release create v${{ env.VERSION }} `
             --title "v${{ env.VERSION }}" `
             --notes "$(Get-Content last_commit_message.txt)" `
-            $nupkgFilePath $snupkgFilePath $perfReportSinkFilePath
+            $nupkgFilePath $snupkgFilePath $perfReportSinkFilePath $perfReportAuditSinkFilePath
         shell: pwsh
 
       - name: Publish to nuget.org
-        env:
-          NUGET_API_KEY: ${{ secrets.NUGET_API_KEY }}
         run: |
           nuget push artifacts\*.nupkg -Source https://api.nuget.org/v3/index.json -ApiKey ${{ secrets.NUGET_API_KEY }}
         shell: pwsh

RunPerfTests.ps1

@@ -1,4 +1,13 @@
-Push-Location $PSScriptRoot
+[CmdletBinding()]
+param (
+    [Parameter(Mandatory = $false)]
+    [string]
+    $Filter = "*"
+)
+
+echo "perf: Performance tests started with Filter = $Filter"
+
+Push-Location $PSScriptRoot
 
 $artifactsPath = "$PSScriptRoot\artifacts\perftests"
 
@@ -13,7 +22,7 @@ $perfTestProjectPath = "$PSScriptRoot/test/Serilog.Sinks.MSSqlServer.Performance
 Push-Location "$perfTestProjectPath"
 
 echo "perf: Running performance test project in $perfTestProjectPath"
-& dotnet run -c Release
+& dotnet run -c Release -- -f $Filter
 
 cp ".\BenchmarkDotNet.Artifacts\results\*.*" "$artifactsPath\"
 Pop-Location

src/Serilog.Sinks.MSSqlServer/Serilog.Sinks.MSSqlServer.csproj

@@ -74,6 +74,7 @@
 
   <ItemGroup>
     <InternalsVisibleTo Include="$(AssemblyName).Tests" PublicKey="0024000004800000940000000602000000240000525341310004000001000100fb8d13fd344a1c6fe0fe83ef33c1080bf30690765bc6eb0df26ebfdf8f21670c64265b30db09f73a0dea5b3db4c9d18dbf6d5a25af5ce9016f281014d79dc3b4201ac646c451830fc7e61a2dfd633d34c39f87b81894191652df5ac63cc40c77f3542f702bda692e6e8a9158353df189007a49da0f3cfd55eb250066b19485ec" />
+    <InternalsVisibleTo Include="$(AssemblyName).PerformanceTests" PublicKey="0024000004800000940000000602000000240000525341310004000001000100fb8d13fd344a1c6fe0fe83ef33c1080bf30690765bc6eb0df26ebfdf8f21670c64265b30db09f73a0dea5b3db4c9d18dbf6d5a25af5ce9016f281014d79dc3b4201ac646c451830fc7e61a2dfd633d34c39f87b81894191652df5ac63cc40c77f3542f702bda692e6e8a9158353df189007a49da0f3cfd55eb250066b19485ec" />
     <InternalsVisibleTo Include="DynamicProxyGenAssembly2" PublicKey="0024000004800000940000000602000000240000525341310004000001000100c547cac37abd99c8db225ef2f6c8a3602f3b3606cc9891605d02baa56104f4cfc0734aa39b93bf7852f7d9266654753cc297e7d2edfe0bac1cdcf9f717241550e0a7b191195b7667bb4f64bcb8e2121380fd1d9d46ad2d92d2d15605093924cceaf74c4861eff62abf69b9291ed0a340e113be11e6a7d3113e92484cf7045cc7" />
   </ItemGroup>
 

test/Serilog.Sinks.MSSqlServer.PerformanceTests/Misc/AuditSinkExtendedBenchmarks.cs

@@ -0,0 +1,67 @@
+using System;
+using System.Collections.Generic;
+using System.Data;
+using BenchmarkDotNet.Attributes;
+
+namespace Serilog.Sinks.MSSqlServer.PerformanceTests.Misc;
+
+[MemoryDiagnoser]
+public class AuditSinkExtendedBenchmarks
+{
+    private const string _connectionString = @"Data Source=(localdb)\MSSQLLocalDB;Database=LogAuditExtPerfTest;Integrated Security=SSPI;Encrypt=False;";
+    private const string _schemaName = "dbo";
+    private const string _tableName = "LogEvents";
+    private ILogger _log = null!;
+    private DateTimeOffset _additionalColumn7;
+
+
+    [Params("String One", "String Two")]
+    public string AdditionalColumn1 { get; set; }
+
+    [Params(1, 2)]
+    public int AdditionalColumn2 { get; set; }
+
+
+    [GlobalSetup]
+    public void Setup()
+    {
+        var options = new ColumnOptions
+        {
+            AdditionalColumns = new List<SqlColumn>
+            {
+                new() { DataType = SqlDbType.NVarChar, ColumnName = "AdditionalColumn1", DataLength = 40 },
+                new() { DataType = SqlDbType.Int, ColumnName = "AdditionalColumn2" },
+                new() { DataType = SqlDbType.Int, ColumnName = "AdditionalColumn3" },
+                new() { DataType = SqlDbType.Int, ColumnName = "AdditionalColumn4" },
+                new() { DataType = SqlDbType.Int, ColumnName = "AdditionalColumn5" },
+                new() { DataType = SqlDbType.Int, ColumnName = "AdditionalColumn6" },
+                new() { DataType = SqlDbType.DateTimeOffset, ColumnName = "AdditionalColumn7" }
+            }
+        };
+        options.Store.Add(StandardColumn.LogEvent);
+        _log = new LoggerConfiguration()
+            .AuditTo.MSSqlServer(_connectionString,
+                sinkOptions: new MSSqlServerSinkOptions
+                {
+                    TableName = _tableName,
+                    SchemaName = _schemaName,
+                    AutoCreateSqlTable = true,
+                    AutoCreateSqlDatabase = true
+                },
+                appConfiguration: null,
+                restrictedToMinimumLevel: Serilog.Events.LogEventLevel.Verbose,
+                formatProvider: null,
+                columnOptions: options,
+                columnOptionsSection: null)
+            .CreateLogger();
+
+        _additionalColumn7 = new DateTimeOffset(2024, 01, 01, 00, 00, 00, TimeSpan.FromHours(1));
+    }
+
+    [Benchmark]
+    public void EmitComplexLogEvent()
+    {
+        _log.Information("Hello, {AdditionalColumn1} {AdditionalColumn2} {AdditionalColumn3} {AdditionalColumn4} {AdditionalColumn5} {AdditionalColumn6} {AdditionalColumn7}!",
+            AdditionalColumn1, AdditionalColumn2, 3, 4, 5, 6, _additionalColumn7);
+    }
+}

test/Serilog.Sinks.MSSqlServer.PerformanceTests/Misc/AuditSinkQuickBenchmarks.cs

@@ -0,0 +1,46 @@
+using BenchmarkDotNet.Attributes;
+
+namespace Serilog.Sinks.MSSqlServer.PerformanceTests.Misc;
+
+[MemoryDiagnoser]
+public class AuditSinkQuickBenchmarks
+{
+    private const string _connectionString = @"Data Source=(localdb)\MSSQLLocalDB;Database=LogAuditQuickPerfTest;Integrated Security=SSPI;Encrypt=False;";
+    private const string _schemaName = "dbo";
+    private const string _tableName = "LogEvents";
+    private ILogger _log = null!;
+
+    [GlobalSetup]
+    public void Setup()
+    {
+        var options = new ColumnOptions();
+        options.Store.Add(StandardColumn.LogEvent);
+        _log = new LoggerConfiguration()
+            .AuditTo.MSSqlServer(_connectionString,
+                sinkOptions: new MSSqlServerSinkOptions
+                {
+                    TableName = _tableName,
+                    SchemaName = _schemaName,
+                    AutoCreateSqlTable = true,
+                    AutoCreateSqlDatabase = true
+                },
+                appConfiguration: null,
+                restrictedToMinimumLevel: Serilog.Events.LogEventLevel.Verbose,
+                formatProvider: null,
+                columnOptions: options,
+                columnOptionsSection: null)
+            .CreateLogger();
+    }
+
+    [Benchmark]
+    public void EmitLogEvent()
+    {
+        _log.Information("Hello, {Name}!", "World");
+    }
+
+    [Benchmark]
+    public void IntProperties()
+    {
+        _log.Information("Hello, {A} {B} {C}!", 1, 2, 3);
+    }
+}

test/Serilog.Sinks.MSSqlServer.PerformanceTests/Misc/SinkExtendedBenchmarks.cs

@@ -0,0 +1,67 @@
+using System;
+using System.Collections.Generic;
+using System.Data;
+using BenchmarkDotNet.Attributes;
+
+namespace Serilog.Sinks.MSSqlServer.PerformanceTests.Misc;
+
+[MemoryDiagnoser]
+public class SinkExtendedBenchmarks
+{
+    private const string _connectionString = @"Data Source=(localdb)\MSSQLLocalDB;Database=LogExtPerfTest;Integrated Security=SSPI;Encrypt=False;";
+    private const string _schemaName = "dbo";
+    private const string _tableName = "LogEvents";
+    private ILogger _log = null!;
+    private DateTimeOffset _additionalColumn7;
+
+
+    [Params("String One", "String Two")]
+    public string AdditionalColumn1 { get; set; }
+
+    [Params(1, 2)]
+    public int AdditionalColumn2 { get; set; }
+
+
+    [GlobalSetup]
+    public void Setup()
+    {
+        var options = new ColumnOptions
+        {
+            AdditionalColumns = new List<SqlColumn>
+            {
+                new() { DataType = SqlDbType.NVarChar, ColumnName = "AdditionalColumn1", DataLength = 40 },
+                new() { DataType = SqlDbType.Int, ColumnName = "AdditionalColumn2" },
+                new() { DataType = SqlDbType.Int, ColumnName = "AdditionalColumn3" },
+                new() { DataType = SqlDbType.Int, ColumnName = "AdditionalColumn4" },
+                new() { DataType = SqlDbType.Int, ColumnName = "AdditionalColumn5" },
+                new() { DataType = SqlDbType.Int, ColumnName = "AdditionalColumn6" },
+                new() { DataType = SqlDbType.DateTimeOffset, ColumnName = "AdditionalColumn7" }
+            }
+        };
+        options.Store.Add(StandardColumn.LogEvent);
+        _log = new LoggerConfiguration()
+            .WriteTo.MSSqlServer(_connectionString,
+                sinkOptions: new MSSqlServerSinkOptions
+                {
+                    TableName = _tableName,
+                    SchemaName = _schemaName,
+                    AutoCreateSqlTable = true,
+                    AutoCreateSqlDatabase = true
+                },
+                appConfiguration: null,
+                restrictedToMinimumLevel: Serilog.Events.LogEventLevel.Verbose,
+                formatProvider: null,
+                columnOptions: options,
+                columnOptionsSection: null)
+            .CreateLogger();
+
+        _additionalColumn7 = new DateTimeOffset(2024, 01, 01, 00, 00, 00, TimeSpan.FromHours(1));
+    }
+
+    [Benchmark]
+    public void EmitComplexLogEvent()
+    {
+        _log.Information("Hello, {AdditionalColumn1} {AdditionalColumn2} {AdditionalColumn3} {AdditionalColumn4} {AdditionalColumn5} {AdditionalColumn6} {AdditionalColumn7}!",
+            AdditionalColumn1, AdditionalColumn2,3, 4, 5, 6, _additionalColumn7);
+    }
+}

test/Serilog.Sinks.MSSqlServer.PerformanceTests/SinkBenchmarks.cs → test/Serilog.Sinks.MSSqlServer.PerformanceTests/Misc/SinkQuickBenchmarks.cs

@@ -1,11 +1,11 @@
 using BenchmarkDotNet.Attributes;
 
-namespace Serilog.Sinks.MSSqlServer.PerformanceTests;
+namespace Serilog.Sinks.MSSqlServer.PerformanceTests.Misc;
 
 [MemoryDiagnoser]
-public class SinkBenchmarks
+public class SinkQuickBenchmarks
 {
-    private const string _connectionString = @"Data Source=(localdb)\MSSQLLocalDB;Database=LogTest;Integrated Security=SSPI;Encrypt=False;";
+    private const string _connectionString = @"Data Source=(localdb)\MSSQLLocalDB;Database=LogQuickPerfTest;Integrated Security=SSPI;Encrypt=False;";
     private const string _schemaName = "dbo";
     private const string _tableName = "LogEvents";
     private ILogger _log = null!;

test/Serilog.Sinks.MSSqlServer.PerformanceTests/Program.cs

@@ -2,16 +2,10 @@
 
 namespace Serilog.Sinks.MSSqlServer.PerformanceTests;
 
-/// <summary>
-/// Wrappers that make it easy to run benchmark suites through the <c>dotnet test</c> runner.
-/// </summary>
-/// <example>
-/// <code>dotnet test -c Release --filter "FullyQualifiedName=Serilog.Sinks.MSSqlServer.PerformanceTests.Harness.Pipeline"</code>
-/// </example>
-public class Program
+public static class Program
 {
-    public static void Main()
+    public static void Main(string[] args)
     {
-        BenchmarkRunner.Run<SinkBenchmarks>();
+        BenchmarkSwitcher.FromAssembly(typeof(Program).Assembly).Run(args);
     }
 }

test/Serilog.Sinks.MSSqlServer.PerformanceTests/Serilog.Sinks.MSSqlServer.PerformanceTests.csproj

@@ -15,6 +15,7 @@
   <ItemGroup>
     <ProjectReference Include="..\..\src\Serilog.Sinks.MSSqlServer\Serilog.Sinks.MSSqlServer.csproj"/>
     <PackageReference Include="BenchmarkDotNet" />
+    <PackageReference Include="Moq" />
   </ItemGroup>
 
 </Project>

test/Serilog.Sinks.MSSqlServer.PerformanceTests/Sinks/MSSqlServer/Platform/SqlBulkBatchWriterBenchmarks.cs

@@ -0,0 +1,64 @@
+using System;
+using System.Collections.Generic;
+using System.Data;
+using System.Threading.Tasks;
+using BenchmarkDotNet.Attributes;
+using Moq;
+using Serilog.Events;
+using Serilog.Parsing;
+using Serilog.Sinks.MSSqlServer.Output;
+using Serilog.Sinks.MSSqlServer.Platform;
+using Serilog.Sinks.MSSqlServer.Platform.SqlClient;
+
+namespace Serilog.Sinks.MSSqlServer.PerformanceTests.Platform;
+
+[MemoryDiagnoser]
+[MaxIterationCount(20)]
+public class SqlBulkBatchWriterBenchmarks
+{
+    private const string _tableName = "TestTableName";
+    private const string _schemaName = "TestSchemaName";
+    private Mock<ISqlConnectionFactory> _sqlConnectionFactoryMock;
+    private Mock<ILogEventDataGenerator> _logEventDataGeneratorMock;
+    private Mock<ISqlConnectionWrapper> _sqlConnectionWrapperMock;
+    private Mock<ISqlBulkCopyWrapper> _sqlBulkCopyWrapper;
+    private SqlBulkBatchWriter _sut;
+
+    [GlobalSetup]
+    public void Setup()
+    {
+        _sqlConnectionFactoryMock = new Mock<ISqlConnectionFactory>();
+        _logEventDataGeneratorMock = new Mock<ILogEventDataGenerator>();
+        _sqlConnectionWrapperMock = new Mock<ISqlConnectionWrapper>();
+        _sqlBulkCopyWrapper = new Mock<ISqlBulkCopyWrapper>();
+
+        _sqlConnectionFactoryMock.Setup(f => f.Create()).Returns(_sqlConnectionWrapperMock.Object);
+        _sqlConnectionWrapperMock.Setup(c => c.CreateSqlBulkCopy(It.IsAny<bool>(), It.IsAny<string>()))
+            .Returns(_sqlBulkCopyWrapper.Object);
+
+        _sut = new SqlBulkBatchWriter(_tableName, _schemaName, false, _sqlConnectionFactoryMock.Object,
+            _logEventDataGeneratorMock.Object);
+    }
+
+    [Benchmark]
+    public async Task WriteBatch()
+    {
+        var logEvents = CreateLogEvents();
+        using var dataTable = new DataTable(_tableName);
+        await _sut.WriteBatch(logEvents, dataTable);
+    }
+
+    private static List<LogEvent> CreateLogEvents()
+    {
+        var logEvents = new List<LogEvent> { CreateLogEvent(), CreateLogEvent() };
+        return logEvents;
+    }
+
+    private static LogEvent CreateLogEvent()
+    {
+        return new LogEvent(
+            new DateTimeOffset(2020, 1, 1, 0, 0, 0, 0, TimeSpan.Zero),
+            LogEventLevel.Debug, null, new MessageTemplate(new List<MessageTemplateToken>()),
+            new List<LogEventProperty>());
+    }
+}