.NET EF Core中Executed DbCommand日志是否含延迟及拦截器问题

1. "Executed DbCommand" 日志的时间范围 #

"Executed DbCommand" 记录的时长包含远程数据库通信延迟+数据库自身操作耗时。EF Core在将命令发送到数据库前启动计时，直到收到数据库执行完成的响应后停止计时，这个时间是从命令发出到结果返回的完整周期，涵盖了网络往返和数据库处理的全部时间。

2. 如何实现包含完整延迟的操作日志 #

如果需要记录从业务触发保存到数据库操作完成的全链路时长（比如从调用SaveChangesAsync到所有数据库命令执行完毕），或者更精准的单命令全周期时长，需要使用DbCommandInterceptor而非SaveChanges拦截器。

3. 拦截器耗时显示0ms的问题排查与解决 #

问题原因 #

你当前使用的SavingChangesAsync拦截器，执行时机是EF Core开始处理内存中的实体变更（比如验证实体状态、生成SQL语句），但尚未将命令发送到数据库。所以stopwatch测量的只是EF在内存中的处理时间，这个过程极快，因此日志显示0ms，和实际数据库操作的7ms无关。

解决方法 #

改用DbCommandInterceptor来拦截数据库命令的执行，它能准确捕获命令发送到数据库和收到响应的完整周期。示例代码如下：

public class CommandTimingInterceptor : DbCommandInterceptor
{
    private readonly ILogger<CommandTimingInterceptor> _logger;

    public CommandTimingInterceptor(ILogger<CommandTimingInterceptor> logger)
    {
        _logger = logger;
    }

    public override async ValueTask<InterceptionResult<DbDataReader>> ReaderExecutingAsync(
        DbCommand command,
        CommandEventData eventData,
        InterceptionResult<DbDataReader> result,
        CancellationToken cancellationToken = default)
    {
        // 命令执行前启动计时
        eventData.Command.SetStartTime(DateTime.UtcNow);
        return await base.ReaderExecutingAsync(command, eventData, result, cancellationToken);
    }

    public override async ValueTask<DbDataReader> ReaderExecutedAsync(
        DbCommand command,
        CommandExecutedEventData eventData,
        DbDataReader result,
        CancellationToken cancellationToken = default)
    {
        // 命令执行完成后计算耗时
        var startTime = eventData.Command.GetStartTime();
        var duration = DateTime.UtcNow - startTime;
        _logger.LogInformation($"DbCommand executed in {duration.TotalMilliseconds:F2} ms. SQL: {command.CommandText}");

        return await base.ReaderExecutedAsync(command, eventData, result, cancellationToken);
    }

    // 针对非查询命令（如INSERT/UPDATE/DELETE）重写对应方法
    public override async ValueTask<InterceptionResult<int>> NonQueryExecutingAsync(
        DbCommand command,
        CommandEventData eventData,
        InterceptionResult<int> result,
        CancellationToken cancellationToken = default)
    {
        eventData.Command.SetStartTime(DateTime.UtcNow);
        return await base.NonQueryExecutingAsync(command, eventData, result, cancellationToken);
    }

    public override async ValueTask<int> NonQueryExecutedAsync(
        DbCommand command,
        CommandExecutedEventData eventData,
        int result,
        CancellationToken cancellationToken = default)
    {
        var startTime = eventData.Command.GetStartTime();
        var duration = DateTime.UtcNow - startTime;
        _logger.LogInformation($"NonQuery DbCommand executed in {duration.TotalMilliseconds:F2} ms. SQL: {command.CommandText}");

        return await base.NonQueryExecutedAsync(command, eventData, result, cancellationToken);
    }
}

// 扩展方法存储命令开始时间
public static class CommandExtensions
{
    private static readonly ConditionalWeakTable<DbCommand, DateTime> _startTimes = new();

    public static void SetStartTime(this DbCommand command, DateTime startTime)
    {
        _startTimes.AddOrUpdate(command, startTime);
    }

    public static DateTime GetStartTime(this DbCommand command)
    {
        return _startTimes.TryGetValue(command, out var startTime) ? startTime : DateTime.UtcNow;
    }
}

注册拦截器 #

在DbContext的配置中注册这个拦截器：

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
{
    optionsBuilder.AddInterceptors(new CommandTimingInterceptor(_logger));
}

这样就能准确记录每个数据库命令从发送到响应的完整耗时，包含网络延迟和数据库处理时间，和"Executed DbCommand"的日志时长一致，还可以自定义输出SQL语句等额外信息。

内容的提问来源于stack exchange，提问作者Nikola Vetnić