Qiita Teams that are logged in
You are not logged in to any team

Log in to Qiita Team
Community
OrganizationAdvent CalendarQiitadon (β)
Service
Qiita JobsQiita ZineQiita Blog
11
Help us understand the problem. What is going on with this article?
@Nossa

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

More than 1 year has passed since last update.

はじめに

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 文が走るので2重に登録される心配はない
    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.csMainメソッドに 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 に切り替わるタイミングを見逃していて「全件取得した後に、メモリ内でフィルタリングしていた」などのミスにもログの確認で気づけます。

11
Help us understand the problem. What is going on with this article?
Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
Nossa
C#、TypeScriptが好きです。

Comments

No comments
Sign up for free and join this conversation.
Sign Up
If you already have a Qiita account Login
11
Help us understand the problem. What is going on with this article?