Add EF Core-style logging for bulk insert operations

src/PhenX.EntityFrameworkCore.BulkInsert.MySql/MySqlBulkInsertProvider.cs

@@ -12,7 +12,7 @@
 namespace PhenX.EntityFrameworkCore.BulkInsert.MySql;
 
 [UsedImplicitly]
-internal class MySqlBulkInsertProvider(ILogger<MySqlBulkInsertProvider> logger) : BulkInsertProviderBase<MySqlServerDialectBuilder, MySqlBulkInsertOptions>(logger)
+internal class MySqlBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<MySqlServerDialectBuilder, MySqlBulkInsertOptions>(loggerFactory)
 {
     //language=sql
     /// <inheritdoc />

src/PhenX.EntityFrameworkCore.BulkInsert.Oracle/OracleBulkInsertProvider.cs

@@ -11,7 +11,7 @@
 namespace PhenX.EntityFrameworkCore.BulkInsert.Oracle;
 
 [UsedImplicitly]
-internal class OracleBulkInsertProvider(ILogger<OracleBulkInsertProvider>? logger) : BulkInsertProviderBase<OracleDialectBuilder, OracleBulkInsertOptions>(logger)
+internal class OracleBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<OracleDialectBuilder, OracleBulkInsertOptions>(loggerFactory)
 {
     /// <inheritdoc />
     protected override string BulkInsertId => "ROWID";

src/PhenX.EntityFrameworkCore.BulkInsert.PostgreSql/PostgreSqlBulkInsertProvider.cs

@@ -15,7 +15,7 @@
 namespace PhenX.EntityFrameworkCore.BulkInsert.PostgreSql;
 
 [UsedImplicitly]
-internal class PostgreSqlBulkInsertProvider(ILogger<PostgreSqlBulkInsertProvider>? logger) : BulkInsertProviderBase<PostgreSqlDialectBuilder, PostgreSqlBulkInsertOptions>(logger)
+internal class PostgreSqlBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<PostgreSqlDialectBuilder, PostgreSqlBulkInsertOptions>(loggerFactory)
 {
     //language=sql
     /// <inheritdoc />

src/PhenX.EntityFrameworkCore.BulkInsert.SqlServer/SqlServerBulkInsertProvider.cs

@@ -10,7 +10,7 @@
 namespace PhenX.EntityFrameworkCore.BulkInsert.SqlServer;
 
 [UsedImplicitly]
-internal class SqlServerBulkInsertProvider(ILogger<SqlServerBulkInsertProvider>? logger) : BulkInsertProviderBase<SqlServerDialectBuilder, SqlServerBulkInsertOptions>(logger)
+internal class SqlServerBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<SqlServerDialectBuilder, SqlServerBulkInsertOptions>(loggerFactory)
 {
     //language=sql
     /// <inheritdoc />

src/PhenX.EntityFrameworkCore.BulkInsert.Sqlite/SqliteBulkInsertProvider.cs

@@ -13,7 +13,7 @@
 namespace PhenX.EntityFrameworkCore.BulkInsert.Sqlite;
 
 [UsedImplicitly]
-internal class SqliteBulkInsertProvider(ILogger<SqliteBulkInsertProvider>? logger) : BulkInsertProviderBase<SqliteDialectBuilder, BulkInsertOptions>(logger)
+internal class SqliteBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<SqliteDialectBuilder, BulkInsertOptions>(loggerFactory)
 {
     private const int MaxParams = 1000;
 

src/PhenX.EntityFrameworkCore.BulkInsert/BulkInsertOptionsExtension.cs

@@ -16,8 +16,8 @@ public DbContextOptionsExtensionInfo Info
 
     public void ApplyServices(IServiceCollection services)
     {
-        services.TryAddSingleton(typeof(ILogger<>), typeof(NullLogger<>));
-        services.AddSingleton<IBulkInsertProvider, TProvider>();
+        services.TryAddSingleton<ILoggerFactory, NullLoggerFactory>();
+        services.AddScoped<IBulkInsertProvider, TProvider>();
     }
 
     public void Validate(IDbContextOptions options)

src/PhenX.EntityFrameworkCore.BulkInsert/BulkInsertProviderBase.cs

@@ -1,3 +1,4 @@
+using System.Diagnostics;
 using System.Runtime.CompilerServices;
 
 using Microsoft.EntityFrameworkCore;
@@ -11,10 +12,12 @@
 
 namespace PhenX.EntityFrameworkCore.BulkInsert;
 
-internal abstract class BulkInsertProviderBase<TDialect, TOptions>(ILogger? logger) : BulkInsertProviderUntyped<TDialect, TOptions>
+internal abstract class BulkInsertProviderBase<TDialect, TOptions>(ILoggerFactory? loggerFactory) : BulkInsertProviderUntyped<TDialect, TOptions>
     where TDialect : SqlDialectBuilder, new()
     where TOptions : BulkInsertOptions, new()
 {
+    private ILogger? _logger;
+    private ILogger? logger => _logger ??= loggerFactory?.CreateLogger(GetType());
     protected virtual string BulkInsertId => "_bulk_insert_id";
 
     protected abstract string AddTableCopyBulkInsertId { get; }
@@ -144,7 +147,15 @@ private async Task<string> PerformBulkInsertAsync<T>(
         activity?.AddTag("tempTable", tempTableRequired);
         activity?.AddTag("synchronous", sync);
 
+        var sw = Stopwatch.StartNew();
         await BulkInsert(sync, context, tableInfo, entities, tableName, columns, options, ctk);
+        sw.Stop();
+
+        if (logger != null)
+        {
+            Log.BulkInsertExecuted(logger, sw.ElapsedMilliseconds, tableInfo.QuotedTableName);
+        }
+
         return tableName;
     }
 
@@ -254,7 +265,7 @@ protected virtual Task DropTempTableAsync(bool sync, DbContext dbContext, string
         return Task.CompletedTask;
     }
 
-    protected static async Task ExecuteAsync(
+    protected async Task ExecuteAsync(
         bool sync,
         DbContext context,
         string query,
@@ -264,6 +275,7 @@ protected static async Task ExecuteAsync(
         command.Transaction = context.Database.CurrentTransaction!.GetDbTransaction();
         command.CommandText = query;
 
+        var sw = Stopwatch.StartNew();
         if (sync)
         {
             // ReSharper disable once MethodHasAsyncOverloadWithCancellation
@@ -273,5 +285,11 @@ protected static async Task ExecuteAsync(
         {
             await command.ExecuteNonQueryAsync(ctk);
         }
+        sw.Stop();
+
+        if (logger != null)
+        {
+            Log.ExecutedDbCommand(logger, sw.ElapsedMilliseconds, query);
+        }
     }
 }

src/PhenX.EntityFrameworkCore.BulkInsert/Log.cs

@@ -27,4 +27,16 @@ internal static partial class Log
         Level = LogLevel.Error,
         Message = "Failed to drop temporary table.")]
     public static partial void DropTemporaryTableFailed(ILogger logger, Exception exception);
+
+    [LoggerMessage(
+        EventId = 1004,
+        Level = LogLevel.Information,
+        Message = "Executed BulkInsert ({ElapsedMs}ms) [DestinationTable='{DestinationTable}']")]
+    public static partial void BulkInsertExecuted(ILogger logger, long elapsedMs, string destinationTable);
+
+    [LoggerMessage(
+        EventId = 1005,
+        Level = LogLevel.Debug,
+        Message = "Executed DbCommand ({ElapsedMs}ms)\n{CommandText}")]
+    public static partial void ExecutedDbCommand(ILogger logger, long elapsedMs, string commandText);
 }

tests/PhenX.EntityFrameworkCore.BulkInsert.Tests/Tests/Logging/CapturingLogger.cs

@@ -0,0 +1,41 @@
+using Microsoft.Extensions.Logging;
+
+namespace PhenX.EntityFrameworkCore.BulkInsert.Tests.Tests.Logging;
+
+internal sealed record LogEntry(LogLevel Level, EventId EventId, string Message);
+
+internal sealed class CapturingLogger : ILogger
+{
+    private readonly List<LogEntry> _entries;
+
+    public CapturingLogger(List<LogEntry> entries)
+    {
+        _entries = entries;
+    }
+
+    public IDisposable? BeginScope<TState>(TState state) where TState : notnull => NullScope.Instance;
+
+    public bool IsEnabled(LogLevel logLevel) => true;
+
+    public void Log<TState>(
+        LogLevel logLevel,
+        EventId eventId,
+        TState state,
+        Exception? exception,
+        Func<TState, Exception?, string> formatter)
+    {
+        _entries.Add(new LogEntry(logLevel, eventId, formatter(state, exception)));
+    }
+
+    private sealed class NullScope : IDisposable
+    {
+        public static readonly NullScope Instance = new();
+        public void Dispose() { }
+    }
+}
+
+internal sealed class CapturingLoggerProvider(List<LogEntry> entries) : ILoggerProvider
+{
+    public ILogger CreateLogger(string categoryName) => new CapturingLogger(entries);
+    public void Dispose() { }
+}

tests/PhenX.EntityFrameworkCore.BulkInsert.Tests/Tests/Logging/LoggingTests.cs

@@ -0,0 +1,132 @@
+using FluentAssertions;
+
+using Microsoft.Data.Sqlite;
+using Microsoft.EntityFrameworkCore;
+using Microsoft.Extensions.Logging;
+
+using PhenX.EntityFrameworkCore.BulkInsert.Extensions;
+using PhenX.EntityFrameworkCore.BulkInsert.Sqlite;
+using PhenX.EntityFrameworkCore.BulkInsert.Tests.DbContext;
+
+using Xunit;
+
+namespace PhenX.EntityFrameworkCore.BulkInsert.Tests.Tests.Logging;
+
+[Trait("Category", "Sqlite")]
+public class LoggingTests
+{
+    [Fact]
+    public async Task BulkInsert_LogsBulkInsertExecuted_AtInformationLevel()
+    {
+        // Arrange
+        var logEntries = new List<LogEntry>();
+        using var loggerFactory = LoggerFactory.Create(builder =>
+            builder
+                .AddProvider(new CapturingLoggerProvider(logEntries))
+                .SetMinimumLevel(LogLevel.Debug));
+
+        await using var connection = new SqliteConnection("DataSource=:memory:");
+        await connection.OpenAsync();
+
+        var context = new TestDbContextSqlite
+        {
+            ConfigureOptions = builder => builder
+                .UseSqlite(connection)
+                .UseLoggerFactory(loggerFactory)
+                .UseBulkInsertSqlite(),
+        };
+        await context.Database.EnsureCreatedAsync();
+
+        var run = Guid.NewGuid();
+        var entities = new List<TestEntity>
+        {
+            new TestEntity { TestRun = run, Name = "Entity1" },
+            new TestEntity { TestRun = run, Name = "Entity2" },
+        };
+
+        // Act
+        await context.ExecuteBulkInsertAsync(entities);
+
+        // Assert
+        logEntries.Should().Contain(e =>
+            e.Level == LogLevel.Information &&
+            e.EventId.Id == 1004 &&
+            e.Message.Contains("Executed BulkInsert"));
+    }
+
+    [Fact]
+    public async Task BulkInsert_LogsDbCommands_AtDebugLevel()
+    {
+        // Arrange
+        var logEntries = new List<LogEntry>();
+        using var loggerFactory = LoggerFactory.Create(builder =>
+            builder
+                .AddProvider(new CapturingLoggerProvider(logEntries))
+                .SetMinimumLevel(LogLevel.Debug));
+
+        await using var connection = new SqliteConnection("DataSource=:memory:");
+        await connection.OpenAsync();
+
+        var context = new TestDbContextSqlite
+        {
+            ConfigureOptions = builder => builder
+                .UseSqlite(connection)
+                .UseLoggerFactory(loggerFactory)
+                .UseBulkInsertSqlite(),
+        };
+        await context.Database.EnsureCreatedAsync();
+
+        var run = Guid.NewGuid();
+        var entities = new List<TestEntity>
+        {
+            new TestEntity { TestRun = run, Name = "Entity1" },
+        };
+
+        // Act - ReturnEntities always uses a temp table, triggering auxiliary SQL commands
+        await context.ExecuteBulkInsertReturnEntitiesAsync(entities);
+
+        // Assert
+        logEntries.Should().Contain(e =>
+            e.Level == LogLevel.Debug &&
+            e.EventId.Id == 1005 &&
+            e.Message.Contains("Executed DbCommand"));
+    }
+
+    [Fact]
+    public async Task BulkInsert_LogMessageContainsTableName()
+    {
+        // Arrange
+        var logEntries = new List<LogEntry>();
+        using var loggerFactory = LoggerFactory.Create(builder =>
+            builder
+                .AddProvider(new CapturingLoggerProvider(logEntries))
+                .SetMinimumLevel(LogLevel.Information));
+
+        await using var connection = new SqliteConnection("DataSource=:memory:");
+        await connection.OpenAsync();
+
+        var context = new TestDbContextSqlite
+        {
+            ConfigureOptions = builder => builder
+                .UseSqlite(connection)
+                .UseLoggerFactory(loggerFactory)
+                .UseBulkInsertSqlite(),
+        };
+        await context.Database.EnsureCreatedAsync();
+
+        var run = Guid.NewGuid();
+        var entities = new List<TestEntity>
+        {
+            new TestEntity { TestRun = run, Name = "Entity1" },
+        };
+
+        // Act
+        await context.ExecuteBulkInsertAsync(entities);
+
+        // Assert
+        logEntries.Should().Contain(e =>
+            e.Level == LogLevel.Information &&
+            e.EventId.Id == 1004 &&
+            e.Message.Contains("test_entity"));
+    }
+}