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

在最近的幾個 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` 即可：
    
    ```json
    {
      "Logging": {
        "LogLevel": {
          "Default": "Information",
          "Microsoft": "Warning",
          "Microsoft.Hosting.Lifetime": "Information",
          "Microsoft.EntityFrameworkCore.Database.Command": "Information"
        }
      }
    }
    ```
    
    假設我們對 `Course` 實體查詢的程式碼如下：
    
    ```csharp
    var course = await _context.Courses.FindAsync(1));
    ```
    
    預設輸出的 Log 內容，並不會包含實際傳到資料庫的查詢參數值(`1`)，只有 SQL 語法而已，這是因為**個資保護法**造成的變化：
    
    ```log
    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` 方法
    
    請將以下這段程式：
    
    ```csharp
    services.AddDbContext<ContosoUniversityContext>(options =>
    {
        options.UseSqlServer(Configuration.GetConnectionString("DefaultConnection"));
    });
    ```
    
    修改為以下，也就是加上 `options.EnableSensitiveDataLogging();` 設定：
    
    ```csharp
    services.AddDbContext<ContosoUniversityContext>(options =>
    {
        options.UseSqlServer(Configuration.GetConnectionString("DefaultConnection"));
    
        options.EnableSensitiveDataLogging();
    });
    ```
    
    啟用「敏感資料」紀錄的結果，你的紀錄內容就會變成這樣：
    
    ```log
    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](https://learn.microsoft.com/en-us/ef/core/logging-events-diagnostics/simple-logging) 機制，可以用相當簡易的方式紀錄 EF Core 執行的過程。這個機制跟我們在 EF6 的時候使用的 `db.Database.Log` 很像，但有點不太一樣。舊的 EF6 只能單純紀錄 ORM 轉譯後 SQL 語法，但 EF Core 5.0 卻還可以紀錄各種 EF Core 執行過程產生的各種事件資料。

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

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

修改為以下即可：

```csharp
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](https://learn.microsoft.com/en-us/dotnet/api/system.action-1?view=net-5.0))

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

```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`)
    
    ```csharp
    options.LogTo(Console.WriteLine, LogLevel.Information);
    ```
    
2.  設定紀錄等級並篩選紀錄類別
    
    ```csharp
    options.LogTo(Console.WriteLine, new[] { DbLoggerCategory.Database.Name }, LogLevel.Information);
    ```
    
    這個設定就可以讓我們特別篩選出 `Microsoft.EntityFrameworkCore.Database.Command` 紀錄類別就好。
    

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

```csharp
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` 方法中。

### 相關連結

-   [Overview of logging and interception - EF Core | Microsoft Docs](https://learn.microsoft.com/en-us/ef/core/logging-events-diagnostics/?tabs=v3&WT.mc_id=DT-MVP-4015686#other-applications)
    -   [Simple logging](https://learn.microsoft.com/en-us/ef/core/logging-events-diagnostics/simple-logging?WT.mc_id=DT-MVP-4015686)
    -   [Using Microsoft.Extensions.Logging](https://learn.microsoft.com/en-us/ef/core/logging-events-diagnostics/extensions-logging?WT.mc_id=DT-MVP-4015686&tabs=v3)
-   [Logging in Entity Framework Core](https://www.entityframeworktutorial.net/efcore/logging-in-entityframework-core.aspx)
-   [Entity Framework Core: Show Parameter Values in Logging | by Eric Anderson | ITNEXT](https://itnext.io/entity-framework-core-show-parameter-values-in-logging-5ac58b6a4929)
-   [Data Points - Logging SQL and Change-Tracking Events in EF Core | Microsoft Docs](https://learn.microsoft.com/en-us/archive/msdn-magazine/2018/october/data-points-logging-sql-and-change-tracking-events-in-ef-core?WT.mc_id=DT-MVP-4015686)
-   [EntityFrameworkCore Logging in ASP.NET Core](https://wildermuth.com/2018/11/07/EntityFrameworkCore-Logging-in-ASP-NET-Core)
-   Logging EF Core actions to a file using Serilog