The Will Will Web

記載著 Will 在網路世界的學習心得與技術分享

ASP.NET Core 如何紀錄 Entity Framework Core 5.0 自動產生的 SQL 命令

📅 2020/12/13 01:44 📁 .NET Core, Entity Framework

在最近的幾個 Entity Framework Core 版本，對於 Logging (紀錄) 的撰寫方式一直在改變，大致上可區分成 EF Core 2.1, EF Core 3.0+ 與 EF Core 5.0 三種版本，這意味著你從網路上找到的資訊，很有可能是舊的，但很多人無法區別其差異，因為舊的寫法到了 EF Core 5.0 依然可以用，只是會被標示棄用而已。你應該也可以想像得到，越新的 EF Core 版本，寫法就會更簡單的，這篇文章我就來說說幾種不同的紀錄方法。

為什麼要紀錄 EF Core 自動產生的 SQL 命令

由於 Entity Framework Core 是一套相當完整的 ORM 框架，我們可以利用 ORM 架構幫我們對資料進行建模(Modeling)，用「物件導向」的方式描述一份資料，方便我們可以用相對「抽象」的方式來存取資料。不過，有些時候透過 ORM 框架自動產生的 SQL 語法，可能會導致執行效能低落，這時我們就可以透過 Logging 的方式，將 EF Core 自動產生的 SQL 命令印出來（或寫到檔案中），藉此進一步分析如何優化這些 SQL 語法的執行效率。

我們在做 Entity Framework 效能調教的時候，比較常見的方法是將複雜的查詢語法，改用預存程序(Stored Procedure)或檢視表(Views)來改善執行效率，但更多時候可能只是加入「索引」就可以大幅改善查詢效能。如果遇到需要批次新增、更新或刪除資料的情況，也會透過直接執行 SQL 的方式來執行，封裝成預存程序也是另一種可行的方案。

最簡單的紀錄方法

其實要紀錄 EF Core 自動產生的 SQL 命令，最簡單的方式，就是直接調整 Logging 的組態設定，而且從舊版 EF Core 到最新的 EF Core 5.0 都可以用。基本上你只需要設定兩個步驟：

  1. 編輯 appsettings.Development.json 組態設定

    你只要在 Logging:LogLevel 加入 Microsoft.EntityFrameworkCore.Database.Command 並將其設定為 Information 即可：

    {
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Information",
      "Microsoft.EntityFrameworkCore.Database.Command": "Information"
    }
  }
}

    假設我們對 Course 實體查詢的程式碼如下：

    var course = await _context.Courses.FindAsync(1));

    預設輸出的 Log 內容，並不會包含實際傳到資料庫的查詢參數值(1)，只有 SQL 語法而已，這是因為個資保護法造成的變化：

    info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (35ms) [Parameters=[@__p_0='?'], CommandType='Text', CommandTimeout='30']
      SELECT TOP(1) [c].[CourseID], [c].[Credits], [c].[DepartmentID], [c].[Title]
      FROM [Course] AS [c]
      WHERE [c].[CourseID] = @__p_0

    要顯示上述 @__p_0 的參數值，就要進一步調整程式碼。

  2. 編輯 Startup 類別的 ConfigureServices 方法

    請將以下這段程式：

    services.AddDbContext<ContosoUniversityContext>(options =>
{
    options.UseSqlServer(Configuration.GetConnectionString("DefaultConnection"));
});

    修改為以下，也就是加上 options.EnableSensitiveDataLogging(); 設定：

    services.AddDbContext<ContosoUniversityContext>(options =>
{
    options.UseSqlServer(Configuration.GetConnectionString("DefaultConnection"));

    options.EnableSensitiveDataLogging();
});

    啟用「敏感資料」紀錄的結果，你的紀錄內容就會變成這樣：

    info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (35ms) [Parameters=[@__p_0='1'], CommandType='Text', CommandTimeout='30']
      SELECT TOP(1) [c].[CourseID], [c].[Credits], [c].[DepartmentID], [c].[Title]
      FROM [Course] AS [c]
      WHERE [c].[CourseID] = @__p_0

簡單兩個步驟，真的蠻實用的，各位可以參考看看！ 👍

使用 Simple Logging 方法

EF Core 5.0 新增一個 Simple Logging 機制，可以用相當簡易的方式紀錄 EF Core 執行的過程。這個機制跟我們在 EF6 的時候使用的 db.Database.Log 很像，但有點不太一樣。舊的 EF6 只能單純紀錄 ORM 轉譯後 SQL 語法，但 EF Core 5.0 卻還可以紀錄各種 EF Core 執行過程產生的各種事件資料。

設定方式，就是修改你在 Startup 類別的 ConfigureServices 方法，將以下這段程式：

services.AddDbContext<ContosoUniversityContext>(options =>
{
    options.UseSqlServer(Configuration.GetConnectionString("DefaultConnection"));
    options.EnableSensitiveDataLogging();
});

修改為以下即可：

services.AddDbContext<ContosoUniversityContext>(options =>
{
    options.UseSqlServer(Configuration.GetConnectionString("DefaultConnection"));
    options.EnableSensitiveDataLogging();

    options.LogTo(Console.WriteLine);
});

你可以從上述範例程式看到，其實 options.LogTo() 的使用方式跟 EF6 的 db.Database.Log() 相當類似，也很容易上手，反正傳入一個 Action<string> 就可以用任何自訂的邏輯來紀錄 EF Core 執行的過程。(參考：Action<T> Delegate)

不過，如果你真的看了 Log 輸出的結果，你會發現這份紀錄比你想像的還複雜很多，因為紀錄的內容真的很多：

warn: Microsoft.EntityFrameworkCore.Model.Validation[10400]
      Sensitive data logging is enabled. Log entries and exception messages may include sensitive application data; this mode should only be enabled during development.
warn: 2020/12/13 01:00:00.008 CoreEventId.SensitiveDataLoggingEnabledWarning[10400] (Microsoft.EntityFrameworkCore.Infrastructure)
      Sensitive data logging is enabled. Log entries and exception messages may include sensitive application data; this mode should only be enabled during development.
info: 2020/12/13 01:00:00.111 CoreEventId.ContextInitialized[10403] (Microsoft.EntityFrameworkCore.Infrastructure)
      Entity Framework Core 5.0.0 initialized 'ContosoUniversityContext' using provider 'Microsoft.EntityFrameworkCore.SqlServer' with options: SensitiveDataLoggingEnabled
dbug: 2020/12/13 01:00:00.165 CoreEventId.QueryCompilationStarting[10111] (Microsoft.EntityFrameworkCore.Query)
      Compiling query expression:
      'DbSet<Course>()
          .FirstOrDefault(e => EF.Property<int>(e, "CourseId") == __p_0)'
dbug: 2020/12/13 01:00:00.278 CoreEventId.QueryExecutionPlanned[10107] (Microsoft.EntityFrameworkCore.Query)
      Generated query execution expression:
      'queryContext => ShapedQueryCompilingExpressionVisitor.SingleOrDefaultAsync<Course>(
          asyncEnumerable: new SingleQueryingEnumerable<Course>(
              (RelationalQueryContext)queryContext,
              RelationalCommandCache.SelectExpression(
                  Projection Mapping:
                      EmptyProjectionMember -> Dictionary<IProperty, int> { [Property: Course.CourseId (int) Required PK AfterSave:Throw ValueGenerated.OnAdd, 0], [Property: Course.Credits (int) Required, 1], [Property: Course.DepartmentId (int) Required FK Index ValueGenerated.OnAdd, 2], [Property: Course.Title (string) MaxLength(50), 3], }
                  SELECT TOP(1) c.CourseID, c.Credits, c.DepartmentID, c.Title
                  FROM Course AS c
                  WHERE c.CourseID == @__p_0),
              Func<QueryContext, DbDataReader, ResultContext, SingleQueryResultCoordinator, Course>,
              WebApplication4.Models.ContosoUniversityContext,
              False,
              False
          ),
          cancellationToken: queryContext.CancellationToken)'
dbug: 2020/12/13 01:00:00.323 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 2020/12/13 01:00:00.327 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (18ms).
dbug: 2020/12/13 01:00:00.336 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opening connection to database 'ContosoUniversity' on server '(localdb)\MSSQLLocalDB'.
dbug: 2020/12/13 01:00:00.492 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opened connection to database 'ContosoUniversity' on server '(localdb)\MSSQLLocalDB'.
dbug: 2020/12/13 01:00:00.498 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@__p_0='1'], CommandType='Text', CommandTimeout='30']
      SELECT TOP(1) [c].[CourseID], [c].[Credits], [c].[DepartmentID], [c].[Title]
      FROM [Course] AS [c]
      WHERE [c].[CourseID] = @__p_0
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (37ms) [Parameters=[@__p_0='1'], CommandType='Text', CommandTimeout='30']
      SELECT TOP(1) [c].[CourseID], [c].[Credits], [c].[DepartmentID], [c].[Title]
      FROM [Course] AS [c]
      WHERE [c].[CourseID] = @__p_0
info: 2020/12/13 01:00:00.535 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (37ms) [Parameters=[@__p_0='1'], CommandType='Text', CommandTimeout='30']
      SELECT TOP(1) [c].[CourseID], [c].[Credits], [c].[DepartmentID], [c].[Title]
      FROM [Course] AS [c]
      WHERE [c].[CourseID] = @__p_0
dbug: 2020/12/13 01:00:00.564 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'ContosoUniversityContext' started tracking 'Course' entity with key '{CourseId: 1}'.
dbug: 2020/12/13 01:00:00.584 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
dbug: 2020/12/13 01:00:00.587 RelationalEventId.ConnectionClosing[20002] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closing connection to database 'ContosoUniversity' on server '(localdb)\MSSQLLocalDB'.
dbug: 2020/12/13 01:00:00.590 RelationalEventId.ConnectionClosed[20003] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closed connection to database 'ContosoUniversity' on server '(localdb)\MSSQLLocalDB'.
dbug: 2020/12/13 01:00:00.603 CoreEventId.ContextDisposed[10407] (Microsoft.EntityFrameworkCore.Infrastructure)
      'ContosoUniversityContext' disposed.

很多時候我們還真的只想要 SQL 語法而已，此時你有兩種降低紀錄詳細程度的方法：

  1. 設定紀錄等級 (LogLevel)

    options.LogTo(Console.WriteLine, LogLevel.Information);

  2. 設定紀錄等級並篩選紀錄類別

    options.LogTo(Console.WriteLine, new[] { DbLoggerCategory.Database.Name }, LogLevel.Information);

    這個設定就可以讓我們特別篩選出 Microsoft.EntityFrameworkCore.Database.Command 紀錄類別就好。

你當然不止可以紀錄到 Console 裡，也可以輸出到檔案中，你只要到 DbContext 類別 (例如 ContosoUniversityContext 類別) 中加入以下程式碼即可：

private readonly StreamWriter _logStream = new StreamWriter("EFCoreDebug.log", append: true);

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

public override void Dispose()
{
    base.Dispose();
    _logStream.Dispose();
}

public override async ValueTask DisposeAsync()
{
    await base.DisposeAsync();
    await _logStream.DisposeAsync();
}

請注意：你可以將本文所提到的設定寫在 DbContext 的 OnConfiguring() 方法或 Startup 的 ConfigureServices 方法中。

相關連結

留言評論