はじめに
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 に切り替わるタイミングを見逃していて「全件取得した後に、メモリ内でフィルタリングしていた」などのミスにもログの確認で気づけます。