Entity Framework Core——9.日志记录与拦截器

https://docs.microsoft.com/zh-cn/ef/core/logging-events-diagnostics/

1.机制

efcore包含一些用于生成日志、响应时间和或者诊断结果的机制。具体见下表：

机制名称	支持异步	范围	进行配置的位置	用途
简单的日志记录	否	上下文	数据库上下文	开发时日志记录
Microsoft.Extensions.Logging	否	上下文	DI或数据库上下文	生产日志记录
事件	否	上下文	任何位置	对 EF 事件做出反应
拦截器	是	上下文	数据库上下文	进行 EF 操作
诊断侦听器	否	进程	全局	应用程序诊断

2. 简单的日志记录

直接在OnConfiguring里配置LogTo即可：

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
{
    optionsBuilder.LogTo(Console.WriteLine);
    //或
    optionsBuilder.LogTo(msg=>Console.WriteLine(msg));
}

2.1 日志的详细信息

默认efcore不会将数据的值包含在异常消息中，因为这类数据可能是敏感的。但是在调试时如果能够看到这些值将是非常非常有用的，通过EnableSensitiveDataLogging()启用此功能:

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .LogTo(Console.WriteLine)
        .EnableSensitiveDataLogging();

出于性能方面的考虑，efcore不会将每一次对数据库的调用都用try-catch包裹起来。但这样有时候遇到问题时会很难诊断，特别是当数据库返回null值而模型却不允许null的时候。可以使用EnableDetailedErrors方法，让efcore返回具体的错误信息：

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .LogTo(Console.WriteLine)
        .EnableDetailedErrors();

2.2 日志过滤

1. 通过LogTo的第二个参数控制日志级别：

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(Console.WriteLine, LogLevel.Information);

2. 将EventId（可从 CoreEventId 类或 RelationalEventId 类获取）传入LogTo的第二个参数，以输出指定类型的日志：

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .LogTo(Console.WriteLine, new[] { CoreEventId.ContextDisposed, CoreEventId.ContextInitialized });

3. 也可以根据消息的类别进行过滤

每条日志消息都分配到一个命名的分层记录器类别。 类别为：

类别	说明
Microsoft.EntityFrameworkCore	所有 EF Core 消息
Microsoft.EntityFrameworkCore.Database	所有数据库交互
Microsoft.EntityFrameworkCore.Database.Connection	使用数据库连接
Microsoft.EntityFrameworkCore.Database.Command	使用数据库命令
Microsoft.EntityFrameworkCore.Database.Transaction	使用数据库事务
Microsoft.EntityFrameworkCore.Update	保存实体，排除数据库交互
Microsoft.EntityFrameworkCore.Model	所有模型和元数据交互
Microsoft.EntityFrameworkCore.Model.Validation	模型验证
Microsoft.EntityFrameworkCore.Query	查询，排除数据库交互
Microsoft.EntityFrameworkCore.Infrastructure	常规事件，例如上下文创建
Microsoft.EntityFrameworkCore.Scaffolding	数据库反向工程
Microsoft.EntityFrameworkCore.Migrations	迁移
Microsoft.EntityFrameworkCore.ChangeTracking	更改跟踪交互

比如记录数据库交互的日志：

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .LogTo(Console.WriteLine, new[] { DbLoggerCategory.Database.Name });

4. 自定义过滤器

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .LogTo(
            Console.WriteLine,
            (eventId, logLevel) => logLevel >= LogLevel.Information
                                   || eventId == RelationalEventId.ConnectionOpened
                                   || eventId == RelationalEventId.ConnectionClosed);

2.3 设置日志的内容和格式

默认日志内容是多行显示，第一行包括Loglevel、本地时间、EventId、消息类别，第二行是具体内容：

info: 10/6/2020 10:52:45.581 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      CREATE TABLE "Blogs" (
          "Id" INTEGER NOT NULL CONSTRAINT "PK_Blogs" PRIMARY KEY AUTOINCREMENT,
          "Name" INTEGER NOT NULL
      );
dbug: 10/6/2020 10:52:45.582 RelationalEventId.TransactionCommitting[20210] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committing transaction.
dbug: 10/6/2020 10:52:45.585 RelationalEventId.TransactionCommitted[20202] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committed transaction.

设置DbContextLoggerOptions.DefaultWithUtcTime使用UTC时间和单行显示

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(
        Console.WriteLine,
        LogLevel.Debug,
        DbContextLoggerOptions.UtcTime | DbContextLoggerOptions.SingleLine);

3. 使用Microsoft.Extensions.Logging

默认已支持

4. 事件

efcore包含有以下几个事件

事件	引入的efcore版本	触发时间
DbContext.SavingChanges	5.0	在调用SaveChanges或SaveChangesAsync前
DbContext.SavedChanges	5.0	成功调用SaveChanges 或 SaveChangesAsync之后
DbContext.SaveChangesFailed	5.0	调用SaveChanges 或 SaveChangesAsync失败时
ChangeTracker.Tracked	2.1	context首次跟踪实体后
ChangeTracker.StateChanged	2.1	当被跟踪的实体更改其状态时（首次进行跟踪时不会触发）

示例：

public interface IHasTimestamps
{
    DateTime? Added { get; set; }
    DateTime? Deleted { get; set; }
    DateTime? Modified { get; set; }
}
public BlogsContext()
{
    ChangeTracker.StateChanged += UpdateTimestamps;
    ChangeTracker.Tracked += UpdateTimestamps;
}

private static void UpdateTimestamps(object sender, EntityEntryEventArgs e)
{
    if (e.Entry.Entity is IHasTimestamps entityWithTimestamps)
    {
        switch (e.Entry.State)
        {
            case EntityState.Deleted:
                entityWithTimestamps.Deleted = DateTime.UtcNow;
                Console.WriteLine($"Stamped for delete: {e.Entry.Entity}");
                break;
            case EntityState.Modified:
                entityWithTimestamps.Modified = DateTime.UtcNow;
                Console.WriteLine($"Stamped for update: {e.Entry.Entity}");
                break;
            case EntityState.Added:
                entityWithTimestamps.Added = DateTime.UtcNow;
                Console.WriteLine($"Stamped for insert: {e.Entry.Entity}");
                break;
        }
    }
}

5. 拦截器

可以拦截、修改、禁止efcore的操作。包括低级的数据库操作（如执行命令）和高级的数据库操作（如对SaveChanges的调用）。

5.1 注册拦截器

在OnConfiguring里进行配置

public class ExampleContext : BlogsContext
{
    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
        => optionsBuilder.AddInterceptors(new TaggedQueryCommandInterceptor());
}

5.2 实现数据库拦截器

低级别的数据库拦截涉及到三个接口：

接口	efcore自带实现基类	已截获数据库操作
IDbCommandInterceptor	DbCommandInterceptor	创建命令 执行命令 执行失败
IDbConnectionInterceptor	DbConnectionInterceptor	打开/关闭连接 连接失败
IDbTransactionInterceptor	DbTransactionInterceptor	创建事务 提交事务 回退事务 创建和使用保存点 事务失败

然后使用TagWith方法对查询进行标记：

var blogs1 = context.Blogs.TagWith("Use hint: robust plan").ToList();

创建上面的TaggedQueryCommandInterceptor拦截器：

public class TaggedQueryCommandInterceptor : DbCommandInterceptor
{
    public override InterceptionResult<DbDataReader> ReaderExecuting(DbCommand command,CommandEventData eventData,InterceptionResult<DbDataReader> result)
    {
        ManipulateCommand(command);
        return result;
    }

    public override ValueTask<InterceptionResult<DbDataReader>> ReaderExecutingAsync(DbCommand command,CommandEventData eventData,InterceptionResult<DbDataReader> result,CancellationToken cancellationToken = default)
    {
        ManipulateCommand(command);
        return new ValueTask<InterceptionResult<DbDataReader>>(result);
    }

    private static void ManipulateCommand(DbCommand command)
    {
        if (command.CommandText.StartsWith("-- Use hint: robust plan", StringComparison.Ordinal))
        {
            command.CommandText += " OPTION (ROBUST PLAN)";
        }
    }
}

拦截器同时实现了同步和异步的方法，可应用到同步或异步查询中。此时生成的sql如下：

-- Use hint: robust plan

SELECT [b].[Id], [b].[Name]
FROM [Blogs] AS [b] OPTION (ROBUST PLAN)

5.2.1 示例

需要实现的功能：当查询前先查下缓存，如有有缓存则直接返回。否则将从数据库查询出来的数据存放到缓存中。

以下示例用来获取最新的每天消息：

1. 首先给查询打tag：

async Task<string> GetDailyMessage(DailyMessageContext context)
    => (await context.DailyMessages.TagWith("Get_Daily_Message").OrderBy(e => e.Id).LastAsync()).Message;

2. 设置拦截器需要的一些参数

public class CachingCommandInterceptor : DbCommandInterceptor
{
    private readonly object _lock = new object();
    private int _id;
    private string _message;
    private DateTime _queriedAt;
    
    public override ValueTask<InterceptionResult<DbDataReader>> ReaderExecutingAsync(DbCommand command,CommandEventData eventData,InterceptionResult<DbDataReader> result,CancellationToken cancellationToken = default)
    {
       //...
    }

    public override async ValueTask<DbDataReader> ReaderExecutedAsync(DbCommand command,CommandExecutedEventData eventData,DbDataReader result,CancellationToken cancellationToken = default)
    {
        //...
    }
}

因为拦截器是全局的而且可以应用到多个dbcotext上，所以需要定义一个锁。
3. 在数据库查询执行之前，拦截器根据之前打的tag来定位具体的查询，然后检查是否有缓存

public override ValueTask<InterceptionResult<DbDataReader>> ReaderExecutingAsync(DbCommand command,CommandEventData eventData,InterceptionResult<DbDataReader> result,CancellationToken cancellationToken = default)
{
    if (command.CommandText.StartsWith("-- Get_Daily_Message", StringComparison.Ordinal))
    {
        lock (_lock)
        {
            if (_message != null&& DateTime.UtcNow < _queriedAt + new TimeSpan(0, 0, 10))//查询10s以内的数据
            {
                //因为sql不会到数据库执行，所以可以加一些自定义的注释
                command.CommandText = "-- Get_Daily_Message: Skipping DB call; using cache.";
                result = InterceptionResult<DbDataReader>.SuppressWithResult(new CachedDailyMessageDataReader(_id, _message));
            }
        }
    }

    return new ValueTask<InterceptionResult<DbDataReader>>(result);
}

4. 如果没有发现缓存则会执行到ReaderExecutedAsync方法

public override async ValueTask<DbDataReader> ReaderExecutedAsync(DbCommand command,CommandExecutedEventData eventData,DbDataReader result,CancellationToken cancellationToken = default)
{
    if (command.CommandText.StartsWith("-- Get_Daily_Message", StringComparison.Ordinal)&& !(result is CachedDailyMessageDataReader))
    {
        try
        {
            await result.ReadAsync(cancellationToken);
            lock (_lock)
            {
                _id = result.GetInt32(0);
                _message = result.GetString(1);
                _queriedAt = DateTime.UtcNow;
                return new CachedDailyMessageDataReader(_id, _message);
            }
        }
        finally
        {
            await result.DisposeAsync();
        }
    }

    return result;
}

5.3 对OnSaveChanges的拦截

应用场景：记录某些人对数据做了哪些更改时。

实现方法：有两个数据库上下文，用户对BlogsContext进行更改操作，并配置拦截。AuditContext存储用户的具体操作。

1. 首先配置BlogsContext

public class BlogsContext : DbContext
{
    private readonly AuditingInterceptor _auditingInterceptor = new AuditingInterceptor("DataSource=audit.db");
    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
        => optionsBuilder
            .AddInterceptors(_auditingInterceptor)
            .UseSqlite("DataSource=blogs.db");
    public DbSet<Blog> Blogs { get; set; }
}

主要是配置拦截器
2. AuditContext无须额外设置

public class AuditContext : DbContext
{
    private readonly string _connectionString;

    public AuditContext(string connectionString)
    {
        _connectionString = connectionString;
    }

    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
        => optionsBuilder.UseSqlite(_connectionString);

    public DbSet<SaveChangesAudit> SaveChangesAudits { get; set; }
}

public class SaveChangesAudit
{
    public int Id { get; set; }
    public Guid AuditId { get; set; }
    public DateTime StartTime { get; set; }
    public DateTime EndTime { get; set; }
    public bool Succeeded { get; set; }
    public string ErrorMessage { get; set; }

    public ICollection<EntityAudit> Entities { get; } = new List<EntityAudit>();
}

public class EntityAudit
{
    public int Id { get; set; }
    public EntityState State { get; set; }
    public string AuditMessage { get; set; }

    public SaveChangesAudit SaveChangesAudit { get; set; }
}

3. AuditingInterceptor的实现逻辑
   在SaveChanges时就记录数据，并写入数据库。如果保存失败，则记录操作失败。如果保存成功，则记录操作成功。

实现ISaveChangesInterceptor接口，实现SavingChangesAsync、SavedChangesAsync、SaveChangesFailedAsync三个异步方法和对应的同步方法。

//保存时
public async ValueTask<InterceptionResult<int>> SavingChangesAsync(
    DbContextEventData eventData,
    InterceptionResult<int> result,
    CancellationToken cancellationToken = default)
{
    _audit = CreateAudit(eventData.Context);

    using (var auditContext = new AuditContext(_connectionString))
    {
        auditContext.Add(_audit);
        await auditContext.SaveChangesAsync();
    }

    return result;
}
//保存成功时
public async ValueTask<int> SavedChangesAsync(
    SaveChangesCompletedEventData eventData,
    int result,
    CancellationToken cancellationToken = default)
{
    using (var auditContext = new AuditContext(_connectionString))
    {
        auditContext.Attach(_audit);
        _audit.Succeeded = true;
        _audit.EndTime = DateTime.UtcNow;

        await auditContext.SaveChangesAsync(cancellationToken);
    }

    return result;
}
//保存失败时
public async Task SaveChangesFailedAsync(
    DbContextErrorEventData eventData,
    CancellationToken cancellationToken = default)
{
    using (var auditContext = new AuditContext(_connectionString))
    {
        auditContext.Attach(_audit);
        _audit.Succeeded = false;
        _audit.EndTime = DateTime.UtcNow;
        _audit.ErrorMessage = eventData.Exception.InnerException?.Message;

        await auditContext.SaveChangesAsync(cancellationToken);
    }
}
//创建修改记录
private static SaveChangesAudit CreateAudit(DbContext context)
{
    context.ChangeTracker.DetectChanges();

    var audit = new SaveChangesAudit { AuditId = Guid.NewGuid(), StartTime = DateTime.UtcNow };

    foreach (var entry in context.ChangeTracker.Entries())
    {
        var auditMessage = entry.State switch
        {
            EntityState.Deleted => CreateDeletedMessage(entry),
            EntityState.Modified => CreateModifiedMessage(entry),
            EntityState.Added => CreateAddedMessage(entry),
            _ => null
        };

        if (auditMessage != null)
        {
            audit.Entities.Add(new EntityAudit { State = entry.State, AuditMessage = auditMessage });
        }
    }

    return audit;

    string CreateAddedMessage(EntityEntry entry)
        => entry.Properties.Aggregate(
            $"Inserting {entry.Metadata.DisplayName()} with ",
            (auditString, property) => auditString + $"{property.Metadata.Name}: '{property.CurrentValue}' ");

    string CreateModifiedMessage(EntityEntry entry)
        => entry.Properties.Where(property => property.IsModified || property.Metadata.IsPrimaryKey()).Aggregate(
            $"Updating {entry.Metadata.DisplayName()} with ",
            (auditString, property) => auditString + $"{property.Metadata.Name}: '{property.CurrentValue}' ");

    string CreateDeletedMessage(EntityEntry entry)
        => entry.Properties.Where(property => property.Metadata.IsPrimaryKey()).Aggregate(
            $"Deleting {entry.Metadata.DisplayName()} with ",
            (auditString, property) => auditString + $"{property.Metadata.Name}: '{property.CurrentValue}' ");
}

参考：https://github.com/dotnet/EntityFramework.Docs/blob/main/samples/core/Miscellaneous/SaveChangesInterception/AuditingInterceptor.cs

6. 运行指标

efcore公开了一些指标，通过这些指标我们能观察到程序的以下运行状况：

指标名称	说明
Active DbContexts	当前应用程序中未释放的上下文实例数。 如果此数字持续增长，则可能存在泄漏。 如果启用了 上下文池 ，则此数目是池子中所有的实例总数。
Execution Strategy Operation Failures	数据库操作执行失败的次数。 如果启用重试执行策略，则会在同一操作的多次尝试中包括每个单独的故障。
Optimistic Concurrency Failures	SaveChanges时由于出现了乐观并发错误而失败的次数，主要由 DbUpdateConcurrencyException 引发。
Queries	执行的查询数。
Query Cache Hit Rate (% )	查询时缓存命中率。 第一次执行 LINQ 查询时，EF Core 会将查询树编译为sql并放入缓存中，以便复用。 在普通应用程序的初始预热期后，查询缓存命中率应该稳定在100%。 如果此数字在一段时间内小于100%，则可能会由于重复编译导致性能下降，这可能是由于不理想的动态查询生成导致的。
SaveChanges	已调用 SaveChanges 次数。

6.1 获取指标数据

dotnet-counters工具可以附加到正在运行的进程上，然后获取指标。

1. 首先，通过dotnet tool install --global dotnet-counters安装这个工具。
2. 然后，执行dotnet counters monitor Microsoft.EntityFrameworkCore -p <PID>命令查看指标（PID是进程ID，可以通过任务管理器获取或者PS命令获取）。

Press p to pause, r to resume, q to quit.
 Status: Running

[Microsoft.EntityFrameworkCore]
    Active DbContexts                                               1
    Execution Strategy Operation Failures (Count / 1 sec)           0
    Execution Strategy Operation Failures (Total)                   0
    Optimistic Concurrency Failures (Count / 1 sec)                 0
    Optimistic Concurrency Failures (Total)                         0
    Queries (Count / 1 sec)                                         1
    Queries (Total)                                               189
    Query Cache Hit Rate (%)                                      100
    SaveChanges (Count / 1 sec)                                     0
    SaveChanges (Total)                                             0