记录和拦截数据库操作

注意

仅限 EF6 及更高版本 - 此页面中讨论的功能、API 等已引入实体框架 6。 如果使用的是早期版本,则部分或全部信息不适用。

从 Entity Framework 6 开始,任何时候 Entity Framework 向数据库发送命令时,该命令都可被应用程序代码拦截。 这最常用于日志记录 SQL,但也可用于修改或中止命令。

具体而言,EF 包括:

  • 上下文的 Log 属性,类似于 LINQ to SQL 中的 DataContext.Log
  • 一种机制,用于自定义发送到日志的输出的内容和格式
  • 用于拦截的低级别构建基块,提供更好的控制/灵活性

上下文 Log 属性

对于采用字符串的任何方法,DbContext.Database.Log 属性都可设置为委托。 最常见的用法是,通过将其设置为 TextWriter 的“Write”方法来与任何 TextWriter 一起使用。 当前上下文生成的所有 SQL 都将记录到该编写器中。 例如,以下代码会将 SQL 记录到控制台:

using (var context = new BlogContext())
{
    context.Database.Log = Console.Write;

    // Your code here...
}

注意,context.Database.Log 设置为 Console.Write。 这是将 SQL 记录到控制台所需的全部内容。

让我们添加一些简单的查询/插入/更新代码,以便可以看到一些输出:

using (var context = new BlogContext())
{
    context.Database.Log = Console.Write;

    var blog = context.Blogs.First(b => b.Title == "One Unicorn");

    blog.Posts.First().Title = "Green Eggs and Ham";

    blog.Posts.Add(new Post { Title = "I do not like them!" });

    context.SaveChanges();
}

它会生成以下输出:

SELECT TOP (1)
    [Extent1].[Id] AS [Id],
    [Extent1].[Title] AS [Title]
    FROM [dbo].[Blogs] AS [Extent1]
    WHERE (N'One Unicorn' = [Extent1].[Title]) AND ([Extent1].[Title] IS NOT NULL)
-- Executing at 10/8/2013 10:55:41 AM -07:00
-- Completed in 4 ms with result: SqlDataReader

SELECT
    [Extent1].[Id] AS [Id],
    [Extent1].[Title] AS [Title],
    [Extent1].[BlogId] AS [BlogId]
    FROM [dbo].[Posts] AS [Extent1]
    WHERE [Extent1].[BlogId] = @EntityKeyValue1
-- EntityKeyValue1: '1' (Type = Int32)
-- Executing at 10/8/2013 10:55:41 AM -07:00
-- Completed in 2 ms with result: SqlDataReader

UPDATE [dbo].[Posts]
SET [Title] = @0
WHERE ([Id] = @1)
-- @0: 'Green Eggs and Ham' (Type = String, Size = -1)
-- @1: '1' (Type = Int32)
-- Executing asynchronously at 10/8/2013 10:55:41 AM -07:00
-- Completed in 12 ms with result: 1

INSERT [dbo].[Posts]([Title], [BlogId])
VALUES (@0, @1)
SELECT [Id]
FROM [dbo].[Posts]
WHERE @@ROWCOUNT > 0 AND [Id] = scope_identity()
-- @0: 'I do not like them!' (Type = String, Size = -1)
-- @1: '1' (Type = Int32)
-- Executing asynchronously at 10/8/2013 10:55:41 AM -07:00
-- Completed in 2 ms with result: SqlDataReader

(请注意,此输出假定已执行任何数据库初始化操作。如果尚未执行数据库初始化,则会有更多的输出显示迁移在后台所做的所有工作,以检查或创建新数据库。)

记录哪些信息?

设置 Log 属性后,将记录以下所有内容:

  • 用于所有不同类型命令的 SQL。 例如:
    • 查询,包括常规的 LINQ 查询、eSQL 查询和来自 SqlQuery 等方法的原始查询
    • SaveChanges 操作过程中生成的插入、更新和删除
    • 关系加载查询,如延迟加载生成的查询
  • 参数
  • 命令是否异步执行
  • 指示命令何时开始执行的时间戳
  • 命令是否成功完成,是否因引发异常而失败,或者是否取消(针对异步命令)
  • 结果值的一些指示
  • 执行命令所花费的大致时间。 请注意,这是从发送命令到返回结果对象的时间。 不包括读取结果的时间。

查看上面的示例输出,记录的四个命令包括:

  • 调用 context.Blogs.First 产生的查询
    • 请注意,获取 SQL 的 ToString 方法不适用于此查询,因为“First”不提供可调用 ToString 的 IQueryable
  • 延迟加载 blog.Posts 产生的查询
    • 请注意发生延迟加载的键值的参数详细信息
    • 仅记录设置为非默认值的参数的属性。 例如,只有当 Size 属性为非零时,才会显示。
  • SaveChangesAsync 生成的两个命令;一个用于更新以更改帖子标题,另一个用于插入以添加新帖子
    • 请注意 FK 和 Title 属性的参数详细信息
    • 请注意,这些命令是异步执行的

记录到不同的地方

如上所示,登录到控制台非常简单。 使用不同类型的 TextWriter 也可轻松将日志记录到内存、文件等。

如果熟悉 LINQ to SQL,你可能会注意到,在 LINQ to SQL 中,Log 属性设置为实际的 TextWriter 对象(例如 Console.Out),而 EF 中的 Log 属性则设置为接受字符串的方法(例如 Console.Write 或 Console.Out.Write)。 这样做的原因是通过接受任何可充当字符串接收器的委托,来将 EF 与 TextWriter 分离。 例如,假设已有一些记录框架,并且它定义了如下所示的日志记录方法:

public class MyLogger
{
    public void Log(string component, string message)
    {
        Console.WriteLine("Component: {0} Message: {1} ", component, message);
    }
}

可挂接到 EF 的 Log 属性,如下所示:

var logger = new MyLogger();
context.Database.Log = s => logger.Log("EFApp", s);

结果日志记录

在将命令发送到数据库之前,默认记录器会记录命令文本 (SQL)、参数和带有时间戳的“正在执行”行。 执行命令后,会记录包含运行时间的“已完成”行。

请注意,对于异步命令,在异步任务实际完成、失败或取消之前,不会记录“已完成”行。

“已完成”行包含不同的信息,具体取决于命令的类型以及执行是否成功。

成功执行

对于成功完成的命令,输出为“Completed in x ms with result:”,后面是关于结果的一些指示。 对于返回数据读取器的命令,结果指示是返回的 DbDataReader 的类型。 对于返回整数值的命令,例如上面显示的 update 命令,显示的结果是该整数。

执行失败

对于因引发异常而失败的命令,输出包含来自异常的消息。 例如,使用 SqlQuery 查询确实存在的表将导致如以下所示的日志输出:

SELECT * from ThisTableIsMissing
-- Executing at 5/13/2013 10:19:05 AM
-- Failed in 1 ms with error: Invalid object name 'ThisTableIsMissing'.

已取消执行

对于取消任务的异步命令,结果可能会失败并出现异常,因为这是尝试取消时基础 ADO.NET 提供程序通常执行的操作。 如果未发生这种情况,并且任务完全取消,则输出将如下所示:

update Blogs set Title = 'No' where Id = -1
-- Executing asynchronously at 5/13/2013 10:21:10 AM
-- Canceled in 1 ms

更改日志内容和格式设置

Database.Log 属性在后台使用 DatabaseLogFormatter 对象。 此对象有效地将 IDbCommandInterceptor 实现(见下文)绑定到接受字符串和 DbContext 的委托。 这意味着在 EF 执行命令之前和之后会调用 DatabaseLogFormatter 上的方法。 这些 DatabaseLogFormatter 方法收集和格式化日志输出,并将其发送到委托。

自定义 DatabaseLogFormatter

通过创建一个派生自 DatabaseLogFormatter 并适当替代方法的新类,可以更改记录的内容及其格式。 最常见的替代方法是:

  • LogCommand - 替代此选项可更改命令在执行前的记录方式。 默认情况下,LogCommand 会针对每个参数调用 LogParameter;可选择在替代中执行相同的操作或以不同的方式处理参数。
  • LogResult - 替代此选项可更改执行命令结果的记录方式。
  • LogParameter - 替代此选项可更改参数记录的格式和内容。

例如,假设我们只想在每个命令发送到数据库之前记录一行。 可通过两个替代来完成:

  • 替代 LogCommand 以格式化和写入单行 SQL
  • 替代 LogResult,不执行任何操作。

代码将如下所示:

public class OneLineFormatter : DatabaseLogFormatter
{
    public OneLineFormatter(DbContext context, Action<string> writeAction)
        : base(context, writeAction)
    {
    }

    public override void LogCommand<TResult>(
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        Write(string.Format(
            "Context '{0}' is executing command '{1}'{2}",
            Context.GetType().Name,
            command.CommandText.Replace(Environment.NewLine, ""),
            Environment.NewLine));
    }

    public override void LogResult<TResult>(
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
    }
}

若要记录输出,只需调用 Write 方法,该方法会将输出发送到配置的写入委托。

(请注意,作为示例,此代码删除了换行符。此操作可能不适用于查看复杂的 SQL。)

设置 DatabaseLogFormatter

创建一个新的 DatabaseLogFormatter 类后,需要向 EF 注册该类。 使用基于代码的配置完成此操作。 简而言之,这意味着在与 DbContext 类相同的程序集中创建一个派生自 DbConfiguration 的新类,然后在这个新类的构造函数中调用 SetDatabaseLogFormatter。 例如:

public class MyDbConfiguration : DbConfiguration
{
    public MyDbConfiguration()
    {
        SetDatabaseLogFormatter(
            (context, writeAction) => new OneLineFormatter(context, writeAction));
    }
}

使用新的 DatabaseLogFormatter

现在,只要设置了 Database.Log,就会使用这个新的 DatabaseLogFormatter。 因此,运行第 1 部分中的代码现在将导致以下输出:

Context 'BlogContext' is executing command 'SELECT TOP (1) [Extent1].[Id] AS [Id], [Extent1].[Title] AS [Title]FROM [dbo].[Blogs] AS [Extent1]WHERE (N'One Unicorn' = [Extent1].[Title]) AND ([Extent1].[Title] IS NOT NULL)'
Context 'BlogContext' is executing command 'SELECT [Extent1].[Id] AS [Id], [Extent1].[Title] AS [Title], [Extent1].[BlogId] AS [BlogId]FROM [dbo].[Posts] AS [Extent1]WHERE [Extent1].[BlogId] = @EntityKeyValue1'
Context 'BlogContext' is executing command 'update [dbo].[Posts]set [Title] = @0where ([Id] = @1)'
Context 'BlogContext' is executing command 'insert [dbo].[Posts]([Title], [BlogId])values (@0, @1)select [Id]from [dbo].[Posts]where @@rowcount > 0 and [Id] = scope_identity()'

拦截构建基块

到目前为止,我们了解了如何使用 DbContext.Database.Log 来记录 EF 生成的 SQL。 相较某些低级别构建基块,此代码实际上外观相对较窄,用于更常见的拦截。

拦截接口

拦截代码是围绕拦截接口的概念构建的。 这些接口继承自 IDbInterceptor,并定义在 EF 执行某个操作时调用的方法。 意图是为每种被拦截的对象类型提供一个接口。 例如,IDbCommandInterceptor 接口定义在 EF 调用 ExecuteNonQuery、ExecuteScalar、ExecuteReader 和相关方法之前调用的方法。 同样,该接口还会定义在这些操作完成时调用的方法。 以上所示的 DatabaseLogFormatter 类实现此接口来记录命令。

拦截上下文

如果查看在任何侦听器接口上定义的方法,显而易见,每个调用都给定一个类型为 DbInterceptionContext 的对象,或派生自它的某种类型的对象,例如 DbCommandInterceptionContext<>。 此对象包含有关 EF 正在采取的操作的上下文信息。 例如,如果代表 DbContext 执行操作,则 DbContext 包含在 DbInterceptionContext 中。 同样,对于异步执行的命令,在 DbCommandInterceptionContext 上设置 IsAsync 标志。

结果处理

DbCommandInterceptionContext<> 类包含名为 Result、OriginalResult、Exception 和 OriginalException 的属性。 对于在操作执行前(即针对 ...Executing 方法)调用的拦截方法的调用,这些属性将设置为 NULL/零。 如果操作执行成功,则将 Result 和 OriginalResult 设置为操作的结果。 然后可以在拦截方法中查看这些值(拦截方法在操作执行后调用,即在 ...Executed 方法上调用)。 同样,如果操作引发异常,则将设置 Exception 和 OriginalException 属性。

禁止执行

如果侦听器在命令执行之前(其中一种 ...Executing 方法)设置 Result 属性,那么 EF 将不会尝试实际执行该命令,而只会使用结果集。 换句话说,侦听器可以取消命令的执行,但会继续执行 EF,如同执行命令一样。

使用此方法的一个示例:使用包装提供程序执行的命令批处理。 侦听器会将命令存储为批处理,以便稍后执行,但会向 EF假装该命令已正常执行。 请注意,实现批处理还需更多操作,此示例只是展示如何使用更改的拦截结果。

也可通过在 ...Executing 方法之一中设置 Exception 属性来取消执行。 这将导致 EF 继续执行操作,就像引发的给定异常导致操作执行失败一样。 当然,这可能会导致应用程序崩溃,但也可能是由 EF 处理的暂时性异常或其他异常。 例如,在命令执行失败时,可在测试环境中使用它来测试应用程序的行为。

执行后更改结果

如果侦听器在命令执行后设置 Result 属性(在其中一个 ...Executed 方法中),则 EF 将使用更改后的结果,而不是实际从操作中返回的结果。 同样,如果侦听器在执行命令后设置 Exception 属性,则 EF 将引发设置异常,就好像操作引发了异常一样。

侦听器还可将 Exception 属性设置为 NULL,以指示不应引发异常。 如果执行操作失败,但侦听器希望 EF 继续,仿佛操作成功一样,则此方法会很有用。 这通常还涉及到设置 Result,以便 EF 继续操作时有结果值可以使用。

OriginalResult 和 OriginalException

EF 执行操作后,如果执行没有失败,它将设置 Result 和 OriginalResult 属性,如果执行失败并出现异常,则将设置 Exception 和 OriginalException 属性。

OriginalResult 和 OriginalException 为只读属性,并且仅在实际执行操作后由 EF 设置。 侦听器不能设置这些属性。 这意味着任何侦听器都可区分由其他拦截器设置的异常或结果,而不是执行操作时发生的真实异常或结果。

注册侦听器

创建了一个或多个拦截接口的类后,就可使用 DbInterception 类向 EF 进行注册。 例如:

DbInterception.Add(new NLogCommandInterceptor());

侦听器也可使用 DbConfiguration 基于代码的配置机制在应用程序域级别注册。

示例:记录到 NLog

让我们通过使用 IDbCommandInterceptor 和 NLog 的一个示例来回顾所有内容:

  • 为非异步执行的任何命令记录警告
  • 为执行时引发异常的任何命令记录错误

下面是执行日志记录的类,应如下所示进行注册:

public class NLogCommandInterceptor : IDbCommandInterceptor
{
    private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

    public void NonQueryExecuting(
        DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
        LogIfNonAsync(command, interceptionContext);
    }

    public void NonQueryExecuted(
        DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
        LogIfError(command, interceptionContext);
    }

    public void ReaderExecuting(
        DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        LogIfNonAsync(command, interceptionContext);
    }

    public void ReaderExecuted(
        DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        LogIfError(command, interceptionContext);
    }

    public void ScalarExecuting(
        DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        LogIfNonAsync(command, interceptionContext);
    }

    public void ScalarExecuted(
        DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        LogIfError(command, interceptionContext);
    }

    private void LogIfNonAsync<TResult>(
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        if (!interceptionContext.IsAsync)
        {
            Logger.Warn("Non-async command used: {0}", command.CommandText);
        }
    }

    private void LogIfError<TResult>(
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        if (interceptionContext.Exception != null)
        {
            Logger.Error("Command {0} failed with exception {1}",
                command.CommandText, interceptionContext.Exception);
        }
    }
}

请注意此代码是如何使用拦截上下文来发现何时非异步执行命令,以及发现何时在执行命令时出现错误的。