【C#】Entity Framework Core の SQL の実行ログを確認する

はじめに

C# の OR マッパー Entity Framework Core で LINQ to Entities を使用して DB へアクセスする時、どんな SQL が実際に発行されるのかログを出力して確認したい時があります。
ログの出力先は色々ありますが、この記事ではコンソール画面に表示したいと思います。

環境構築

# プロジェクトの作成
dotnet new console -o SqlLogging
# SQL Server LocalDB へアクセスするためのパッケージ
dotnet add ./SqlLogging package Microsoft.EntityFrameworkCore.SqlServer
# コンソールへログを出力するためのパッケージ
dotnet add ./SqlLogging package Microsoft.Extensions.Logging.Console

モデルとデータベースコンテキスト

とりあえずモデルは書籍とします。プライマリキーのID、タイトル、著者名を持ちます。

using System.ComponentModel.DataAnnotations;
namespace SqlLogging {
  class Book {
    public int ID { get; set; }
    [Required] public string Title { get; set; }
    public string AuthorName { get; set; }
  }
}

データベースコンテキストを以下のように編集します。
ログをとるにはDbContextOptionsBuilderでロガーファクトリ(ILoggerFactory)を登録する必要があります。

using Microsoft.EntityFrameworkCore;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Console;

namespace SqlLogging {
  class BooksDbContext : DbContext {
    public DbSet<Book> Books { get; set; }

    // ロガーファクトリに ConsoleLoggerProvider を登録する。
    // 出力先を変えたい時は登録するロガー変えたり、追加する
    static readonly ILoggerFactory loggerFactory = new LoggerFactory(new[] {
          new ConsoleLoggerProvider((category, level) =>
            category == DbLoggerCategory.Database.Command.Name
                && level == LogLevel.Information, true) });

    // UseLoggerFactory で上記のロガーファクトリを登録する。
    // Insert 文の値をロギングするために EnableSensitiveDataLogging を許可する。
    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder) =>
      optionsBuilder
        .EnableSensitiveDataLogging()
        .UseLoggerFactory(loggerFactory)
        .UseSqlServer(@"Server=(localdb)\mssqllocaldb;Database=SampleDb;Trusted_Connection=True;");

    // データベースに初期値をシーディングする。
    // ※データベースに値がない場合のみ Insert 文が走るので２重に登録される心配はない
    protected override void OnModelCreating(ModelBuilder modelBuilder) =>
      modelBuilder.Entity<Book>().HasData(
        new Book {
          ID = 1,
          Title = "アンドロイドは電気羊の夢を見るか?",
          AuthorName = "フィリップ・K・ディック"
        },
        new Book {
          ID = 2,
          Title = "夏への扉",
          AuthorName = "ロバート・A・ハインライン"
        },
        new Book {
          ID = 3,
          Title = "1984年",
          AuthorName = "ジョージ・オーウェル"
        },
        new Book {
          ID = 4,
          Title = "幼年期の終り",
          AuthorName = "アーサー・C・クラーク"
        });
  }
}

データへのアクセス

Program.csのMainメソッドに DB にアクセスする処理を追加します。

using System;
using System.Linq;

namespace SqlLogging {
  class Program {
    static void Main(string[] args) {
      using (var dbContext = new BooksDbContext()) {
        // まだDBがない場合にデータベースを作成。
        // 存在する場合何もしないのでモデルとの整合性は保証されないが、
        // 今回は使い捨てでマイグレーションを行わないのでこれでOK
        dbContext.Database.EnsureCreated();
      }

      using (var dbContext = new BooksDbContext()) {
        var book = dbContext.Books.SingleOrDefault(x => x.ID == 1);
        Console.WriteLine($"{book.Title}-{book.AuthorName}");
      }

      using (var dbContext = new BooksDbContext()) {
        var newBook = new Book {
          Title = "ニューロマンサー", 
          AuthorName = "ウィリアム・ギブスン"
        };
        dbContext.Add(newBook);
        dbContext.SaveChanges();
      }

      using (var dbContext = new BooksDbContext()) {
        var books = dbContext.Books.Where(x => x.Title.Length <= 5);
        foreach (var book in books) {
          Console.WriteLine($"{book.Title}-{book.AuthorName}");
        }
      }
    }
  }
}

SQL ログを出力する

アプリケーションを実行してみます。

PS> dotnet run -p ./SqlLogging

コンソールに SQL ログが流れるのが確認できました。

info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (169ms) [Parameters=[], CommandType='Text', CommandTimeout='60']
      CREATE DATABASE [SampleDb];
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (47ms) [Parameters=[], CommandType='Text', CommandTimeout='60']
      IF SERVERPROPERTY('EngineEdition') <> 5
      BEGIN
          ALTER DATABASE [SampleDb] SET READ_COMMITTED_SNAPSHOT ON;
      END;
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (9ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      CREATE TABLE [Books] (
          [ID] int NOT NULL IDENTITY,
          [Title] nvarchar(max) NOT NULL,
          [AuthorName] nvarchar(max) NULL,
          CONSTRAINT [PK_Books] PRIMARY KEY ([ID])
      );
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (21ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      IF EXISTS (SELECT * FROM [sys].[identity_columns] WHERE [name] IN (N'ID', N'AuthorName', N'Title') AND [object_id] = OBJECT_ID(N'[Books]'))
          SET IDENTITY_INSERT [Books] ON;
      INSERT INTO [Books] ([ID], [AuthorName], [Title])
      VALUES (1, N'フィリップ・K・ディック', N'アンドロイドは電気羊の夢を見るか?'),
      (2, N'ロバート・A・ハインライン', N'夏への扉'),
      (3, N'ジョージ・オーウェル', N'1984年'),
      (4, N'アーサー・C・クラーク', N'幼年期の終り');
      IF EXISTS (SELECT * FROM [sys].[identity_columns] WHERE [name] IN (N'ID', N'AuthorName', N'Title') AND [object_id] = OBJECT_ID(N'[Books]'))
          SET IDENTITY_INSERT [Books] OFF;
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (17ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT TOP(2) [x].[ID], [x].[AuthorName], [x].[Title]
      FROM [Books] AS [x]
      WHERE [x].[ID] = 1
アンドロイドは電気羊の夢を見るか?-フィリップ・K・ディック
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (33ms) [Parameters=[@p0='ウィリアム・ギブスン' (Size = 4000), @p1='ニューロマンサー' (Nullable = false) (Size = 4000)], CommandType='Text', CommandTimeout='30']
      SET NOCOUNT ON;
      INSERT INTO [Books] ([AuthorName], [Title])
      VALUES (@p0, @p1);
      SELECT [ID]
      FROM [Books]
      WHERE @@ROWCOUNT = 1 AND [ID] = scope_identity();
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (1ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT [x].[ID], [x].[AuthorName], [x].[Title]
      FROM [Books] AS [x]
      WHERE CAST(LEN([x].[Title]) AS int) <= 5
夏への扉-ロバート・A・ハインライン
1984年-ジョージ・オーウェル

おわりに

アプリを実際に運用していて、発行された SQL を保存しておき後から確認したい場面は多いので使えそうです。
また、LINQ to Entities からLINQ to Objects に切り替わるタイミングを見逃していて「全件取得した後に、メモリ内でフィルタリングしていた」などのミスにもログの確認で気づけます。