Add CommandInitialized interceptor

Fixes #17261

Part of #626

src/EFCore.Relational/Diagnostics/CommandSource.cs

@@ -13,47 +13,53 @@ namespace Microsoft.EntityFrameworkCore.Diagnostics;
 public enum CommandSource
 {
  /// <summary>
- /// Unknown
+ /// The command was generated from an unknown source. This usually indicates a database provider-generated command.
  /// </summary>
  Unknown,
 
  /// <summary>
- /// Linq Query
+ /// The command was generated from a LINQ query on a <see cref="DbSet{TEntity}"/>.
  /// </summary>
  LinqQuery,
 
  /// <summary>
- /// Save Changes
+ /// The command was generated from a call to <see cref="DbContext.SaveChanges()"/> or
+ /// <see cref="DbContext.SaveChangesAsync(System.Threading.CancellationToken)"/>
  /// </summary>
  SaveChanges,
 
  /// <summary>
- /// Migrations
+ /// The command was generated by EF Core Migrations.
  /// </summary>
  Migrations,
 
  /// <summary>
- /// FromSqlQuery
+ /// The command was generated from a call to <see cref="RelationalQueryableExtensions.FromSqlRaw{TEntity}"/> or
+ /// <see cref="RelationalQueryableExtensions.FromSqlInterpolated{TEntity}"/> 
  /// </summary>
  FromSqlQuery,
 
  /// <summary>
- /// ExecuteSqlRaw
+ /// The command was generated from a call to
+ /// <see cref="RelationalDatabaseFacadeExtensions.ExecuteSqlRaw(DatabaseFacade,string,object[])"/>,
+ /// <see cref="RelationalDatabaseFacadeExtensions.ExecuteSqlRawAsync(DatabaseFacade,string,System.Threading.CancellationToken)"/>,
+ /// <see cref="RelationalDatabaseFacadeExtensions.ExecuteSqlInterpolated"/>,
+ /// or <see cref="RelationalDatabaseFacadeExtensions.ExecuteSqlInterpolatedAsync"/>.
  /// </summary>
  ExecuteSqlRaw,
 
  /// <summary>
- /// ValueGenerator
+ /// The command was generated by a <see cref="ValueGenerator"/>.
  /// </summary>
  ValueGenerator,
 
  /// <summary>
- /// Scaffolding
+ /// The command was generated as part of scaffolding (reverse-engineering) from an existing database.
  /// </summary>
  Scaffolding,
 
  /// <summary>
- /// BulkUpdate
+ /// The command was generated as part of a bulk update.
  /// </summary>
  BulkUpdate
 }

src/EFCore.Relational/Diagnostics/IDbCommandInterceptor.cs

@@ -69,6 +69,21 @@ InterceptionResult<DbCommand> CommandCreating(CommandCorrelatedEventData eventDa
  DbCommand CommandCreated(CommandEndEventData eventData, DbCommand result)
  => result;
 
+ /// <summary>
+ /// Called after EF has initialized <see cref="DbCommand.CommandText"/> and other command configuration.
+ /// </summary>
+ /// <param name="eventData">Contextual information about the command and execution.</param>
+ /// <param name="result">
+ /// The command. This value is typically used as the return value for the implementation of this method.
+ /// </param>
+ /// <returns>
+ /// The result that EF will use.
+ /// A normal implementation of this method for any interceptor that is not attempting to change the result
+ /// is to return the <paramref name="result" /> value passed in.
+ /// </returns>
+ DbCommand CommandInitialized(CommandEndEventData eventData, DbCommand result)
+ => result;
+
  /// <summary>
  /// Called just before EF intends to call <see cref="DbCommand.ExecuteReader()" />.
  /// </summary>

src/EFCore.Relational/Diagnostics/IRelationalCommandDiagnosticsLogger.cs

@@ -64,6 +64,30 @@ DbCommand CommandCreated(
  TimeSpan duration,
  CommandSource commandSource);
 
+ /// <summary>
+ /// Logs for the <see cref="RelationalEventId.CommandInitialized" /> event.
+ /// </summary>
+ /// <param name="connection">The connection.</param>
+ /// <param name="command">The database command object.</param>
+ /// <param name="commandMethod">The type of method that will be called on this command.</param>
+ /// <param name="context">The <see cref="DbContext" /> currently being used, to null if not known.</param>
+ /// <param name="commandId">The correlation ID associated with the given <see cref="DbCommand" />.</param>
+ /// <param name="connectionId">The correlation ID associated with the <see cref="DbConnection" /> being used.</param>
+ /// <param name="startTime">The time that execution began.</param>
+ /// <param name="duration">The duration of the command creation.</param>
+ /// <param name="commandSource">Source of the command.</param>
+ /// <returns>An intercepted result.</returns>
+ DbCommand CommandInitialized(
+ IRelationalConnection connection,
+ DbCommand command,
+ DbCommandMethod commandMethod,
+ DbContext? context,
+ Guid commandId,
+ Guid connectionId,
+ DateTimeOffset startTime,
+ TimeSpan duration,
+ CommandSource commandSource);
+
  /// <summary>
  /// Logs for the <see cref="RelationalEventId.CommandExecuting" /> event.
  /// </summary>

src/EFCore.Relational/Diagnostics/Internal/DbCommandInterceptorAggregator.cs

@@ -53,6 +53,18 @@ public DbCommand CommandCreated(
  return result;
  }
 
+ public DbCommand CommandInitialized(
+ CommandEndEventData eventData,
+ DbCommand result)
+ {
+ for (var i = 0; i < _interceptors.Length; i++)
+ {
+ result = _interceptors[i].CommandInitialized(eventData, result);
+ }
+
+ return result;
+ }
+
  public InterceptionResult<DbDataReader> ReaderExecuting(
  DbCommand command,
  CommandEventData eventData,

src/EFCore.Relational/Diagnostics/Internal/RelationalCommandDiagnosticsLogger.cs

@@ -242,6 +242,107 @@ static string CommandCreated(EventDefinitionBase definition, EventData payload)
 
  #endregion CommandCreated
 
+ #region CommandInitialized
+
+ /// <summary>
+ /// This is an internal API that supports the Entity Framework Core infrastructure and not subject to
+ /// the same compatibility standards as public APIs. It may be changed or removed without notice in
+ /// any release. You should only use it directly in your code with extreme caution and knowing that
+ /// doing so can result in application failures when updating to a new Entity Framework Core release.
+ /// </summary>
+ public virtual DbCommand CommandInitialized(
+ IRelationalConnection connection,
+ DbCommand command,
+ DbCommandMethod commandMethod,
+ DbContext? context,
+ Guid commandId,
+ Guid connectionId,
+ DateTimeOffset startTime,
+ TimeSpan duration,
+ CommandSource commandSource)
+ {
+ var definition = RelationalResources.LogCommandInitialized(this);
+
+ if (ShouldLog(definition))
+ {
+ _suppressCommandCreateExpiration = default;
+
+ definition.Log(this, commandMethod.ToString(), (int)duration.TotalMilliseconds);
+ }
+
+ if (NeedsEventData<IDbCommandInterceptor>(
+ definition, out var interceptor, out var diagnosticSourceEnabled, out var simpleLogEnabled))
+ {
+ _suppressCommandCreateExpiration = default;
+
+ var eventData = BroadcastCommandInitialized(
+ connection.DbConnection,
+ command,
+ context,
+ commandMethod,
+ commandId,
+ connectionId,
+ async: false,
+ startTime,
+ duration,
+ definition,
+ diagnosticSourceEnabled,
+ simpleLogEnabled,
+ commandSource);
+
+ if (interceptor != null)
+ {
+ return interceptor.CommandInitialized(eventData, command);
+ }
+ }
+
+ return command;
+ }
+
+ private CommandEndEventData BroadcastCommandInitialized(
+ DbConnection connection,
+ DbCommand command,
+ DbContext? context,
+ DbCommandMethod executeMethod,
+ Guid commandId,
+ Guid connectionId,
+ bool async,
+ DateTimeOffset startTime,
+ TimeSpan duration,
+ EventDefinition<string, int> definition,
+ bool diagnosticSourceEnabled,
+ bool simpleLogEnabled,
+ CommandSource commandSource)
+ {
+ var eventData = new CommandEndEventData(
+ definition,
+ CommandInitialized,
+ connection,
+ command,
+ context,
+ executeMethod,
+ commandId,
+ connectionId,
+ async,
+ false,
+ startTime,
+ duration,
+ commandSource);
+
+ DispatchEventData(definition, eventData, diagnosticSourceEnabled, simpleLogEnabled);
+
+ return eventData;
+
+ static string CommandInitialized(EventDefinitionBase definition, EventData payload)
+ {
+ var d = (EventDefinition<string, int>)definition;
+ var p = (CommandEndEventData)payload;
+ return d.GenerateMessage(p.ExecuteMethod.ToString(), (int)p.Duration.TotalMilliseconds);
+ }
+ }
+
+ #endregion CommandInitialized
+
  #region CommandExecuting
 
  /// <summary>

src/EFCore.Relational/Diagnostics/RelationalEventId.cs

@@ -37,6 +37,7 @@ private enum Id
  CommandCreating,
  CommandCreated,
  CommandCanceled,
+ CommandInitialized,
 
  // Transaction events
  TransactionStarted = CoreEventId.RelationalBaseId + 200,
@@ -214,6 +215,19 @@ private static EventId MakeCommandId(Id id)
  /// </remarks>
  public static readonly EventId CommandCreated = MakeCommandId(Id.CommandCreated);
 
+ /// <summary>
+ /// A <see cref="DbCommand" /> has been initialized with command text and other parameters.
+ /// </summary>
+ /// <remarks>
+ /// <para>
+ /// This event is in the <see cref="DbLoggerCategory.Database.Command" /> category.
+ /// </para>
+ /// <para>
+ /// This event uses the <see cref="CommandEndEventData" /> payload when used with a <see cref="DiagnosticSource" />.
+ /// </para>
+ /// </remarks>
+ public static readonly EventId CommandInitialized = MakeCommandId(Id.CommandInitialized);
+
  /// <summary>
  /// A database command is executing.
  /// </summary>

src/EFCore.Relational/Diagnostics/RelationalLoggingDefinitions.cs

@@ -340,6 +340,15 @@ public abstract class RelationalLoggingDefinitions : LoggingDefinitions
  [EntityFrameworkInternal]
  public EventDefinitionBase? LogCommandCreated;
 
+ /// <summary>
+ /// This is an internal API that supports the Entity Framework Core infrastructure and not subject to
+ /// the same compatibility standards as public APIs. It may be changed or removed without notice in
+ /// any release. You should only use it directly in your code with extreme caution and knowing that
+ /// doing so can result in application failures when updating to a new Entity Framework Core release.
+ /// </summary>
+ [EntityFrameworkInternal]
+ public EventDefinitionBase? LogCommandInitialized;
+
  /// <summary>
  /// This is an internal API that supports the Entity Framework Core infrastructure and not subject to
  /// the same compatibility standards as public APIs. It may be changed or removed without notice in

src/EFCore.Relational/Properties/RelationalStrings.resx

@@ -495,6 +495,10 @@
  <value>Failed executing DbCommand ({elapsed}ms) [Parameters=[{parameters}], CommandType='{commandType}', CommandTimeout='{commandTimeout}']{newLine}{commandText}</value>
  <comment>Error RelationalEventId.CommandError string string System.Data.CommandType int string string</comment>
  </data>
+ <data name="LogCommandInitialized" xml:space="preserve">
+ <value>Initialized DbCommand for '{executionType}' ({elapsed}ms).</value>
+ <comment>Debug RelationalEventId.CommandInitialized string int</comment>
+ </data>
  <data name="LogCommittedTransaction" xml:space="preserve">
  <value>Committed transaction.</value>
  <comment>Debug RelationalEventId.TransactionCommitted</comment>
@@ -887,4 +891,4 @@
  <data name="VisitChildrenMustBeOverridden" xml:space="preserve">
  <value>'VisitChildren' must be overridden in the class deriving from 'SqlExpression'.</value>
  </data>
-</root>
+</root>

src/EFCore.Relational/Storage/RelationalCommand.cs

@@ -776,11 +776,12 @@ public virtual DbCommand CreateDbCommand(
 
  DbCommand command;
 
- if (logger?.ShouldLogCommandCreate(startTime) == true)
+ var logCommandCreate = logger?.ShouldLogCommandCreate(startTime) == true;
+ if (logCommandCreate)
  {
  _stopwatch.Restart();
 
- var interceptionResult = logger.CommandCreating(
+ var interceptionResult = logger!.CommandCreating(
  connection, commandMethod, context, commandId, connectionId, startTime,
  parameterObject.CommandSource);
 
@@ -832,6 +833,20 @@ public virtual DbCommand CreateDbCommand(
  }
  }
 
+ if (logCommandCreate)
+ {
+ command = logger!.CommandInitialized(
+ connection,
+ command,
+ commandMethod,
+ context,
+ commandId,
+ connectionId,
+ startTime,
+ _stopwatch.Elapsed,
+ parameterObject.CommandSource);
+ }
+
  return command;
  }