• 项目

2018 年 10 月

33 卷，第 10

此文章由机器翻译

数据点-EF Core 中的日志记录 SQL 和更改跟踪事件

通过Julie Lerman

Julie Lerman灵活的日志记录 Api 在.NET Core 中添加已开发一件好事。EF Core 会绑定到这些 Api，可让你以公开各种日志记录和调试来自 EF Core 的信息。

在本月的专栏中，我想要向您介绍一些你可以在运行时，EF Core 中获取的信息的类型的一些方法来呈现该信息，并像往常一样，传递我已在此过程了解各种提示和技巧。

虽然日志记录功能是可用的任何内容，位于.NET Core SDK 之上，您会发现文档中的大多数为 ASP.NET Core 如何使用它。请参见，例如，在 ASP.NET Core 日志记录在官方的 Microsoft doc bit.ly/2OiS4HD。

你可以面向各种目标，得益于 ILoggerFactory，而可以使用内置提供程序，如 ConsoleLoggerProvider 和 DebugLoggerProvider，甚至可以使用 Windows 事件、 AzureAppServices 和的详细信息集成到输出。提供程序封装在各种扩展，如 Microsoft.Extensions.Logging.Console 中。因为我在本文中的目标是向您显示的信息 EF Core 类型可以公开，不是如何与各种提供程序，我建议看一下前面提到的 ASP.NET Core 日志记录文章，以及 Mark Michaelis 文章中，"日志记录与.NET Core"在msdn.com/magazine/mt694089。

在这里，我们将只使用提供程序的输出到控制台和调试程序。

日志记录扩展都依赖于。NET 标准。这意味着您可以使用在.NET Framework 4.6.1 及更高版本的应用程序或.NET Core 和 ASP.NET Core 中的日志记录。ASP.NET Core 中生成的日志记录，因此它更轻松地利用它有很多。但是，我将使用.NET Framework 应用程序和配置日志记录直接在 DbContext 类中为了演示呈现 EF Core 日志记录，因为有已使用从 ASP.NET Core 日志记录的许多示例。

EF Core 日志记录在一般情况下

为了图面 EF Core 日志记录信息，您需要将绑定到 DbContext ILoggerFactory。然后，DbContext 会与该记录器工厂共享信息。ASP.NET Core 会替您，但 ASP.NET Core 之外完成此步骤必须显式。

首先需要定义 LoggerFactory 对象，这是您可以在其中指定 LoggerFactory 应使用哪些提供程序。假设我已有对 Microsoft.Extensions.Logging.Console 和 using 语句对我的 DbContext 类中的命名空间中，这是定义 LoggerFactory 将输出到控制台窗口的最简单方法。

不同的提供程序具有其自己的构造函数定义。例如，ConsoleProvider 具有四个不同的构造函数采用不同的对象来表示提供程序设置。这些构造函数的一种采用 lambda 表达式来呈现一个日志记录级别和日志记录类别。日志记录级别可帮助组织不同类型的日志记录详细信息。一个级别包含日志包含的一些基本信息。另一个分区保存更详细的日志帮助调试问题。与记录器共享其信息的 Api 确定在哪一级别中属于他们的数据。例如，通过 EF Core 提供的数据库命令被标记为信息和调试日志级别。显示由 EF Core 更改跟踪器详细信息被标记为调试级别。我将介绍其中的一些示例。

将类别取决于正在共享的信息的类型。EF Core 2.1 公开 12 不同类别的日志记录信息。在 EF Core LoggerCategory 类bit.ly/2KBLWs1是一个方便的引用，其中你会发现由其派生的类别的列表，如中所示图 1。

图 1 EF Core LoggerCategory 类

ChangeTracking 迁移
Database（数据库） 模型
Database.Command Model.Validation
Database.Connection 基架
Database.Transaction 查询
基础结构 更新

请注意，存在为迁移命令公开事件日志事件。

日志级别和类别轻松地筛选记录器的输出是什么，我将使用的只是 SQL 和 ChangeTracker 详细说明。

检查 EF Core 生成的 SQL

SQL 日志记录生成的 EF Core 活动命令可能会想要使用 EF Core 执行最常见的日志记录任务。当然，您始终可以使用 SQL 事件探查工具，例如 SQL Profiler 用于 Windows，EF Prof 的 (efprof.com) 和 （处于预览状态） 分析功能的跨平台 SQL Operations Studio (bit.ly/2MnfN94)。但您可能始终没有访问这些工具，尤其是如果你想要触发从用户的应用，不在开发人员计算机上的日志。

因此，让我们首先创建输出发送到数据库的 SQL 的记录器工厂。通过 Database.Command 类别公开 SQL 命令。

我将创建名为 DbCommandConsoleLoggerFactory LoggerFactory，然后解释的代码：

public static readonly LoggerFactory DbCommandConsoleLoggerFactory
  = new LoggerFactory (new [] {
      new ConsoleLoggerProvider ((category, level) =>
        category == DbLoggerCategory.Database.Command.Name &&
        level == LogLevel.Information, true)
    });

请注意 LoggerFactory 是静态的。EF 团队 （和文档） 建议的应用程序生存期内，每个上下文实例使用相同的记录器。否则为可能会遇到一些奇怪的副作用，也速度缓慢的 EF Core 的显著处理。使此记录器工厂静态可确保，它将保持处于作用域，可用于在应用程序的整个生存期内的上下文的每个新实例。

记录器工厂可以包含一个或多个提供程序，允许您同时，只要日志传输到多个目标，但我将仅添加一个。此构造函数采用不同的记录器提供程序的数组。定义通过 new [] 数组之后, 我将添加单个提供程序-ConsoleLoggerProvider。该提供程序的四个可用构造函数，我将为一个，我可以使用筛选器使用由类别和日志级别组合成 lambda。第一个参数是我要用于筛选的谓词。我提供变量名称-类别和级别 — 对的值的表达式，然后生成以指示应等于 Database.Command 类的名称 （字符串） 的类别和级别应等于与筛选器LogLevelInformation 枚举。

Database.Command 输出 SQL 以及少量其他 detailsthrough 调试级别，但仅有通过信息级别的 SQL 命令。因此您最好指定只是其中之一 LogLevels 或你将获得冗余命令。调试将命令输出为执行，而信息将作为 Executed 输出它们。

第二个参数是 IncludeScope 选项的布尔值。日志作用域允许到组的日志，但据我所知，EF Core 不会使用它们。  

与定义 LoggerFactory，它必须然后绑定到 DbContext，您可以在 OnConfiguring 方法中执行。UseLoggerFactory 是 DbContextOptionsBuilder 的方法。如果你定义其他选项，如 UseSqlite，可以将附加 UseLoggerFactory。否则，您可以只需调用它直接从 optionsBuilder。无论哪种方式，然后，将传递在类中定义的工厂：

optionsBuilder.UseLoggerFactory(DbCommandConsoleLoggerFactory)

默认情况下，EF Core 将防止公开敏感数据，如筛选器参数值。时调试我自己的代码，我通常添加 EnableSensitiveDataLogging 方法，以公开的：

optionsBuilder.UseLoggerFactory(
  DbCommandConsoleLoggerFactory).EnableSensitiveDataLogging();

与现在设置为公开此数据上下文，我已创建了一些数据并将其保存到我的上下文映射到数据库的控制台应用程序。我要做的所有事情是创建单个杂志，将新项目添加到其项目集合：

using (var context = new PublicationsContext())
{
  var mag = new Magazine("MSDN Magazine", "1105 Media");
  var article = new Article("EF Core 2.1 Query Types","Julie Lerman");
  mag.Articles.Add(article);
  context.Magazines.Add(mag);
  var results=context.SaveChanges();
  Console.ForegroundColor = ConsoleColor.Red;
  Console.WriteLine($"Program Message: The app has stored {results} rows");
}

记录器输出三组跟我程序消息输出的信息 (请参阅图 2)。请注意我混合使用日志记录和控制台 WriteLine 消息此处专门用于此简单演示。但您不应因为没有机会处理冲突和日志记录消息没有到达控制台执行此操作在生产应用程序中。

在信息级别 Database.Commands 上筛选时的日志输出
图 2 在信息级别 Database.Commands 上筛选时的日志输出

每个消息记录器中的以行的开头：

"info: Microsoft.EntityFrameworkCore.Database.Command[20101].
20101 is the unique EventId assigned to Executed DbCommand events.

第一行是 SQLite 发送默认情况下为每个新打开的连接，以确保遵循外键的特殊命令。下一个命令将插入新的杂志，并返回其新生成的主键。最后一个命令将文章以及杂志的键值插入到 MagazineId 外键列，并返回其新生成的主键。最后，控制台应用程序输出我自己的消息，我指定了使用 Console.WriteLine。

请注意信息项说"执行 DbCommand，"甚至中继命令所用执行并将结果返回到 EF Core 以继续处理这些结果的时间。因为我已启用日志记录的敏感数据，还可以查看传入的参数值。

如果我要将日志级别中的信息更改为调试，则输出为稍有不同，如中所示图 3。标志为调试而不是信息。SQL 是仍记录，但作为事件 id 为 20100 的"执行 DbCommand"与其中的事件 id 已 20101 DbCommand 执行的事件。此外，Database.Command 中继来自 SELECT 语句的结果在接收新 PrimaryKeys 后已释放数据读取器时的两个其他事件。

从 LogLevel.Debug Database.Commands
图 3 Database.Commands 从 LogLevel.Debug

让我们看一下输出相同 Database.Commands DebugLoggerProvider。

首先，我将创建另一个 LoggerFactory 这一次一个只需将通过 DebugLoggerProvider 的日志的推送。此提供程序有只有两个构造函数，但其中一种是类似于 ConsoleLoggerProvider 的构造函数，使筛选器 lambda 表达式中，但如果不使用 IncludeScope 参数。我新 LoggerFactory 看起来很接近另：

public static readonly LoggerFactory DbCommandDebugLoggerFactory
  = new LoggerFactory (new [] {
      new DebugLoggerProvider(
        (category, level) => category == DbLoggerCategory.Database.Command.Name &&
                             level == LogLevel.Information)
      );

optionsBuilder.UseLoggerFactory 才能使用此对象，我在控制台显示仅程序消息，并按任何键的输出。

但如果我更改 Visual Studio 输出窗口显示调试输出，我可以看到在 Visual Studio 调试消息之间记录器输出的 SQL 命令。图 4显示一些此输出。请注意，EF Core 日志没有"info"标志或事件 Id，但待办事项列表的日志级别的名称后跟的类别。

Database.Commands 写入到调试窗口的扩展
图 4 Database.Commands 写出到调试窗口

现在让我们看一下更改跟踪类别。EF Core 变更跟踪器的工作原理是对我来说非常有趣，我敢说特别有吸引力？我希望即表示你同意。此类别中的事件的所有在此内调试日志级别。

我将创建另一个 LoggerFactory 同样，使用 ConsoleLoggerProvider，但这次我的筛选器结合了 Database.Commands 和更改跟踪事件。通过对调试级别进行筛选，我可以获得不只是所有的更改跟踪事件，但还捕获的命令的 SQL。请记住该调试引发执行 DbCommand 事件和其他几种：

public static readonly LoggerFactory ChangeTrackingAndSqlConsoleLoggerFactory
  = new LoggerFactory(new[] {
      new ConsoleLoggerProvider (
        (category, level) =>
        (category == DbLoggerCategory.ChangeTracking.Name |
        category==DbLoggerCategory.Database.Command.Name)
        && level==LogLevel.Debug ,true)
  });

切换 optionsBuilder 若要使用此记录器工厂后, 的输出是大不相同 ！该输出的第一个部分所示图 5。如果您不熟悉如何更改跟踪器未能有关其业务，这可能是您特别有趣。请注意，第二个调试以用户身份登录图 5切换上下文名称与实体名称 — 一个已知的 bug 谁的修补程序将会显示在 EF Core 2.2 中。

图 5 的更改跟踪和 Database.Command 类别的事件的第一部分

dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10808]
      'PublicationsContext' generated temporary value '-2147482647' for
      the 'MagazineId' property of new 'Magazine' entity.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10806]
      Context 'Magazine' started tracking '{MagazineId: -2147482647}'
      entity with key 'PublicationsContext'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10808]
      'PublicationsContext' generated temporary value '-2147482647' for
      the 'ArticleId' property of new 'Article' entity.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10806]
      Context 'Article' started tracking '{ArticleId: -2147482647}'
      entity with key PublicationsContext'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10800]
      DetectChanges starting for 'PublicationsContext'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10801]
      DetectChanges completed for 'PublicationsContext'.

如之前，每个条目以开头的类别相关的事件 id。事件开始时我的方法调用上下文。Magazines.Add。

第一个事件是上下文生成新的杂志的临时密钥值 (EventId 10808)，然后开始跟踪 (EventId 10806) 的密钥。接下来，上下文为新的项目重复相同的两个步骤 (EventIds 10808 和 10806 再次)。临时密钥的值是因为它们是不同的实体类型和-2147482647 也是临时密钥值的起始点。

将杂志和其项目添加到上下文之后，我调用 SaveChanges。这会触发 DetectChanges，您可以看到开始日期和结束时间的事件。由于没有任何更改的实体未跟踪的时间，因此要发现，因此这后面紧跟"DetectChanges 已完成"。 请注意，因为它们是新的实体，即使内容已更改，它们的状态仍将添加。

上下文完成检测的更改后，它会开始发送到数据库的 SQL。因此接下来在日志中是外键设置后, 跟插入杂志并返回其新 MagazineId 的命令的特殊 SQLite 命令。

然后更改跟踪器会介入，替换为使用新的数据库生成值 MagazineId 由数据库生成的临时值 — 第一个 Magazine.MagazineId 然后 Article.MagazineId 正在修复：

dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10803]
      Foreign key property 'Magazine.MagazineId' detected as changed from
      '-2147482647' to '17' for entity with key '{MagazineId: 17}'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10803]
      Foreign key property 'Article.MagazineId' detected as changed from
      '-2147482647' to '17' for entity with key '{ArticleId:
      -2147482647}'.

现在项目为 MagazineId 有正确的外键值，而且下一个日志事件是发送 SQL 来将项目插入到数据库的 EF Core。

最后，两个更多的更改跟踪事件都将记录为 EF Core 修改本杂志以及跟踪未更改的文章的已知的状态：

dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10807]
      The 'Magazine' entity with key '{MagazineId: 17}' tracked by
      'PublicationsContext' changed from 'Added' to 'Unchanged'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10807]
      The 'Article' entity with key '{ArticleId: 17}' tracked by
      'PublicationsContext' changed from 'Added' to 'Unchanged'.

我喜欢看到这很明显的布局方式。我一直使用实体框架在十年，我已经花了大量时间调试通过代码和运行时调试器深深深入而监视窗口以了解更改跟踪器的工作原理。

与来自该数据库，尤其是当修改并保存它，数据进行交互的更改跟踪详细信息是非常令人印象深刻。让我们看看，使用新方法，在 GetAndUpdateSomeData图 6，检索了一篇文章，杂志进行编辑，然后保存所做的更改。可以在日志中看到当我运行该查询中，我进行编辑，当我调用 SaveChanges 时，该方法还写出通知 （"查询，""编辑"和"保存"）。

图 6 用于浏览记录的新方法

private static void GetAndUpdateSomeData()
{
  using (var context = new PublicationsContext())
  {
    Console.WriteLine("Query");
    var mag = context.Magazines.Include(m=>m.Articles)
      .FirstOrDefault(m => m.MagazineId == 1);
    Console.WriteLine("Edit");
    mag.Articles.FirstOrDefault().AuthorName += " and Friends";
    Console.WriteLine("Save");
    var results = context.SaveChanges();
    Console.ForegroundColor = ConsoleColor.Red;
    Console.WriteLine($"Program Message: The app has updated {results} rows");
  }

我不会列出整个日志，但它首先显示 MagazineId 1 的 SQL 查询为该杂志。日志用作提醒，在 EF Core 中，某些包括 （值得注意的是适用于集合） 现在分解为单独的查询对数据库因为它是相对于结果的大小和使对象具体化的工作量通常更为有效。返回杂志，另一个事件后，上下文开始跟踪该杂志 — 显示。接下来，EF Core 发送 SQL 来检索有关所有它将返回仅包含一个项目，因为这是我的所有数据，我筛选的杂志文章 (只是一个具有 MagazineId = 1)。下一个事件是在上下文已开始跟踪该文章实体。在此之后，两个事件，该值指示已释放数据读取器-每两个查询的一个。

现在，事情会显得更有趣，如中所示图 7，它显示了日志的其他部分。

图 7 更新过程中的更改跟踪日志

Edit
Save
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10800]
      DetectChanges starting for 'PublicationsContext'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10802]
      Unchanged 'Article.AuthorName' detected as changed from 'Julie Lerman' to
     'Julie Lerman and Friends' and will be marked as modified
      for entity with key '{ArticleId: 1}'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10807]
      The 'Article' entity with key '{ArticleId: 1}' tracked by
      'PublicationsContext' changed from 'Unchanged' to 'Modified'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10801]
      DetectChanges completed for 'PublicationsContext'.
dbug: Microsoft.EntityFrameworkCore.Database.Command[20100]
      Executing DbCommand [Parameters=[], CommandType='Text',
      CommandTimeout='30'] PRAGMA foreign_keys=ON;
dbug: Microsoft.EntityFrameworkCore.Database.Command[20100]
      Executing DbCommand [Parameters=[@p1='1' (DbType = String),
      @p0='Julie Lerman and Friends' (Size = 24)], CommandType='Text',
      CommandTimeout='30']
      UPDATE "Article" SET "AuthorName" = @p0
      WHERE "ArticleId" = @p1;
      SELECT changes();
dbug: Microsoft.EntityFrameworkCore.Database.Command[20300]
      A data reader was disposed.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10807]
      The 'Article' entity with key '{ArticleId: 1}' tracked by
      'PublicationsContext' changed from 'Modified' to 'Unchanged'.

首先注意到我"的编辑"的消息直接跟"保存"消息。即使在上下文当前跟踪我正在编辑的项目，它具有无法更新实时状态信息。它等待，直到调用更改跟踪器 DetectChanges 方法时，在代码中显式或通过其他 EF Core 方法，如 SaveChanges。因此它不是之前我调用 SaveChanges 后该 DetectChanges 开始工作。发现第一件事是 AuthorName 已更改。18082 事件中继该信息，并指示，由于此更改后，它计划将其实体 （其 ArticleId 为 1 的文章） 标记为已修改。下一个事件，18087，指出它只需更改该实体 (ArticleId:1） 从未更改为已修改。这是令人惊叹的详细信息，你正在调试的问题或一些意外的行为，它将是非常有帮助。我对此非常感激 ！（EF 团队为日志记录到 Arthur Vickers hat 提示是他婴儿 ！）

更改跟踪器完成这项工作后，然后可以看到更新方法。同样，我已启用的敏感数据的事实是您可以看到所有 SQL 命令的参数的原因。

在 SQL 末尾"选择更改"是返回受影响的行数的 SQLite 方法。

最后，更改跟踪器清理其跟踪对象，将项目标记为未更改并可供其下一步 adventure 的状态。

不要忘记其他记录器类别

它看起来我必须填充本杂志，以显示其他 10 个 DbLoggerCategory 类型 EF Core 公开的细节。如何公开这些数据中有一个句柄，现在可以试验不同的类别，请参阅它们共享哪些类型的信息。或者，您就可以通过定义的日志记录提供程序不会筛选的任何字段和筛选所有日志记录数据的 EF Core。而不是筛选器谓词表达式，只返回 true 像我在此过得多的信息 (TMI) 工厂中：

public static readonly LoggerFactory TMIConsoleLoggerFactory
  = new LoggerFactory(new[] {
      new ConsoleLoggerProvider ((category, level) => true, false)
  });

虽然日志记录是非常有用的调试问题，我认为对于洞察 API 的工作原理同样重要。和更好地了解其工作原理，它是你将创建将需要要调试的问题的可能性越小。

Julie Lerman住在佛蒙特州的丘陵地区，担任 Microsoft 区域主管、Microsoft MVP、软件团队导师和顾问。可以在全球的用户组和会议中看到她对数据访问和其他主题的介绍。她的博客地址是 thedatafarm.com/blog。她是“Entity Framework 编程”及其 Code First 和 DbContext 版本（全都出版自 O’Reilly Media）的作者。通过 Twitter 关注她：@julielerman 并在 juliel.me/PS-Videos 上观看其 Pluralsight 课程。

衷心感谢以下 Microsoft 技术专家对本文的审阅：Arthur Vickers

在 MSDN 杂志论坛讨论这篇文章