EF Core interceptors, part 2: intercepting database commands

In part 1: how EF Core interceptors work I introduced interceptors and tackled SaveChangesInterceptor. This part covers DbCommandInterceptor.

DbCommandInterceptor lets you intercept every command EF Core sends to a relational database. It wraps each command, with callbacks while the command is built, before it hits the database, and after the database responds.

A common use for this interceptor is detecting slow database commands. I did this on an old project I’m upgrading: the “executed” callbacks compare eventData.Duration against a threshold and log anything slower.

Let’s roll!

Inside DbCommandInterceptor

A command is the DbCommand object EF Core builds for each call to the database. It holds the SQL, its parameters, and the connection it runs on. One SaveChanges call or LINQ query can produce several commands, and the interceptor is called for each one.

EF Core calls your interceptor in three phases for each command:

1. Building the command
   • CommandCreating runs before EF Core creates the DbCommand.
   • CommandCreated runs right after it is created.
   • CommandInitialized runs after EF Core sets the command text and other configuration, so the final SQL is in place.
2. Executing the command
   • The “executing” callback runs just before the command is sent to the database.
   • The “executed” callback runs right after the database call returns.
3. Finishing
   • DataReaderClosing runs just before EF Core closes the data reader, so only for commands that opened one.
   • If something goes wrong, CommandFailed runs when execution throws, and CommandCanceled runs when the command is canceled.

Not every command passes through every step. A command uses only one of the execute pairs, and a failure or cancellation replaces the “executed” step.

Commands are grouped by the result they return:

Group	The command returns	Example SQL	Callbacks
Reader	Rows of data	SELECT * FROM Orders	ReaderExecuting before, ReaderExecuted after
Scalar	One single value	SELECT COUNT(*) FROM Orders	ScalarExecuting before, ScalarExecuted after
Non-query	No data, only a count of affected rows	DELETE FROM Orders WHERE ...	NonQueryExecuting before, NonQueryExecuted after

As you can see, the grouping isn’t random. It follows the DbCommand method EF Core calls (ExecuteReader, ExecuteScalar, or ExecuteNonQuery), and that method decides the result.

The SQL alone doesn’t tell you the group. A LINQ CountAsync() returns one value but still goes through ReaderExecuted. With Npgsql, so do the INSERT and UPDATE commands from SaveChanges. ExecuteDeleteAsync() goes through NonQueryExecuted.

Logging slow commands with DbCommandInterceptor

First, a reasonable threshold must be defined to measure against. Use the options pattern so each environment can set its own value. The 100 ms below is a starting point, so adjust it to your application.

public sealed class SlowCommandOptions
{
    public const string SectionName = "SlowCommands";

    public TimeSpan Threshold { get; init; } = TimeSpan.FromMilliseconds(100);
}

{
  "SlowCommands": {
    "Threshold": "00:00:00.100"
  }
}

Next is the interceptor:

using System.Data.Common;
using Microsoft.EntityFrameworkCore.Diagnostics;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Options;

public sealed class SlowCommandInterceptor(
    IOptions<SlowCommandOptions> options,
    ILogger<SlowCommandInterceptor> logger) : DbCommandInterceptor
{
    private readonly TimeSpan threshold = options.Value.Threshold;

    public override DbDataReader ReaderExecuted(
        DbCommand command,
        CommandExecutedEventData eventData,
        DbDataReader result)
    {
        LogIfSlow(command, eventData);
        return result;
    }

    public override ValueTask<DbDataReader> ReaderExecutedAsync(
        DbCommand command,
        CommandExecutedEventData eventData,
        DbDataReader result,
        CancellationToken cancellationToken = default)
    {
        LogIfSlow(command, eventData);
        return ValueTask.FromResult(result);
    }

    public override object? ScalarExecuted(
        DbCommand command,
        CommandExecutedEventData eventData,
        object? result)
    {
        LogIfSlow(command, eventData);
        return result;
    }

    public override ValueTask<object?> ScalarExecutedAsync(
        DbCommand command,
        CommandExecutedEventData eventData,
        object? result,
        CancellationToken cancellationToken = default)
    {
        LogIfSlow(command, eventData);
        return ValueTask.FromResult(result);
    }

    public override int NonQueryExecuted(
        DbCommand command,
        CommandExecutedEventData eventData,
        int result)
    {
        LogIfSlow(command, eventData);
        return result;
    }

    public override ValueTask<int> NonQueryExecutedAsync(
        DbCommand command,
        CommandExecutedEventData eventData,
        int result,
        CancellationToken cancellationToken = default)
    {
        LogIfSlow(command, eventData);
        return ValueTask.FromResult(result);
    }

    private void LogIfSlow(DbCommand command, CommandExecutedEventData eventData)
    {
        if (eventData.Duration < threshold)
        {
            return;
        }

        logger.LogWarning(
            "Slow {Method} from {Source} took {ElapsedMs:F2} ms: {CommandText}",
            eventData.ExecuteMethod,
            eventData.CommandSource,
            eventData.Duration.TotalMilliseconds,
            command.CommandText);
    }
}

DbCommandInterceptor has no-op virtual methods for every callback, so I override only the “executed” ones. They receive CommandExecutedEventData, which already has a Duration, so there’s no need for a Stopwatch. Each method returns the result it received, so the interceptor only observes.

EF Core calls the sync or async variant depending on how you run the command, so each group needs both overrides. All six call LogIfSlow, which logs how the command ran (ExecuteMethod) and what produced it (CommandSource).

The interceptor is a singleton because it holds no per-request state, so the registration follows that:

builder.Services.Configure<SlowCommandOptions>(
    builder.Configuration.GetSection(SlowCommandOptions.SectionName));

builder.Services.AddSingleton<SlowCommandInterceptor>();

builder.Services.AddDbContext<AppDbContext>((sp, options) =>
    options
        .UseNpgsql(builder.Configuration.GetConnectionString("Default"))
        .AddInterceptors(sp.GetRequiredService<SlowCommandInterceptor>()));

And the result should look like this. The Product entity comes from part 1:

var term = "keyboard";

var matches = await db.Products
    .Where(p => p.Name.ToLower().Contains(term))
    .OrderBy(p => p.Price)
    .Take(20)
    .ToListAsync();

warn: SlowCommandInterceptor[0]
      Slow ExecuteReader from LinqQuery took 165.75 ms: SELECT p."Id", p."CreatedAt", p."CreatedBy", p."Name", p."Price", p."UpdatedAt", p."UpdatedBy"
      FROM "Products" AS p
      WHERE lower(p."Name") LIKE @term_contains
      ORDER BY p."Price"
      LIMIT @p

With the threshold set to 100 ms, a command like this that takes 165.75 ms logs a warning. The SQL contains the parameter placeholders @term_contains and @p; their values are not logged. Commands below the threshold produce no warning.

Decide what to do about the values:

• Leave them out
• Log them only when EF Core allows it: CommandEventData has a LogParameterValues property that indicates whether the application allows logging of parameter values. It’s true when you call EnableSensitiveDataLogging().

Limitations and practical considerations

Before you introduce this interceptor into a project, I suggest getting acquainted with these few pieces of advice.

Command duration is not total query time

The duration covers one call to the database. It leaves out building the LINQ query, waiting for a connection, reading rows, and creating entities.

This means the timer starts once EF Core has made the SQL and is about to tell the database to run it. It stops when that database call returns, and for a query that happens before the rows are read.

So a query that responds quickly and then spends seconds loading rows stays under the threshold. To time the whole request instead, use something like the request timing middleware.

Failed and canceled commands need separate handling

A command that throws doesn’t finish normally, so don’t assume your “executed” code runs for it. Use CommandFailed for exceptions and CommandCanceled for cancellations. Both are more overrides on the same interceptor:

public override void CommandFailed(
    DbCommand command,
    CommandErrorEventData eventData)
{
    LogFailure(command, eventData);
}

public override Task CommandFailedAsync(
    DbCommand command,
    CommandErrorEventData eventData,
    CancellationToken cancellationToken = default)
{
    LogFailure(command, eventData);
    return Task.CompletedTask;
}

public override void CommandCanceled(
    DbCommand command,
    CommandEndEventData eventData)
{
    LogCanceled(command, eventData);
}

public override Task CommandCanceledAsync(
    DbCommand command,
    CommandEndEventData eventData,
    CancellationToken cancellationToken = default)
{
    LogCanceled(command, eventData);
    return Task.CompletedTask;
}

private void LogFailure(DbCommand command, CommandErrorEventData eventData)
{
    logger.LogError(
        eventData.Exception,
        "Command failed after {ElapsedMs:N0} ms: {CommandText}",
        eventData.Duration.TotalMilliseconds,
        command.CommandText);
}

private void LogCanceled(DbCommand command, CommandEndEventData eventData)
{
    logger.LogInformation(
        "Command canceled after {ElapsedMs:N0} ms: {CommandText}",
        eventData.Duration.TotalMilliseconds,
        command.CommandText);
}

Timeouts need this too. With Npgsql, a command that hits its timeout before the first rows arrive throws, so it lands in CommandFailed and skips LogIfSlow. Once ReaderExecuted has run, a timeout or cancellation while reading rows reaches neither CommandFailed nor CommandCanceled.

Keep logging lightweight and protect sensitive data

Check the threshold before preparing detailed messages. Avoid logging parameter values, and remember that SQL text can also contain sensitive literals or comments. EF Core’s sensitive-data logging settings won’t redact information you log yourself.

When to use DbCommandInterceptor

Here is my two-question plan for deciding if my use case suits this interceptor:

1. Do built-in logging and my monitoring tools fall short?
2. Do I need to react to or change commands in code?

If both answers are positive, I introduce it. If all you want is the SQL in your logs, Microsoft’s interceptors docs recommend simple logging or Microsoft.Extensions.Logging instead.