Entity Framework Core - SQLをログで確認する

ef-core

EF Coreでやってみたいことは色々ありますが、まずは実行されるSQLを確認できるようにしておきたいのでログまわりを少し試します。

ドキュメントだとこのあたりですね。

Logging - EF Core | Microsoft Docs

ログを出力する

上記ドキュメントそのままなんですが、ログを出力するためにまずはILoggerProviderとILoggerを実装します。

// ロガープロバイダー
public class AppLoggerProvider : ILoggerProvider {
    // ロガーを生成
    public ILogger CreateLogger(string categoryName) {
        return new ConsoleLogger();
    }

    public void Dispose() {
    }

    // ロガー
    private class ConsoleLogger : ILogger {
        public IDisposable BeginScope<TState>(TState state) => null;
        public bool IsEnabled(LogLevel logLevel) => true;

        // ログを出力
        public void Log<TState>(
            LogLevel logLevel, EventId eventId,
            TState state, Exception exception,
            Func<TState, Exception, string> formatter) {
            // コンソールに出力
            Console.WriteLine(formatter(state, exception));
        }
    }
}

コンソールアプリでは実装したロガープロバイダーをDBコンテキストに設定します。（エンティティとDBコンテキストのコードは前回の記事を参考にしてもらえると。）

using (var dbContext = new AppDbContext()) {
    // ロガープロバイダーを設定する
    var serviceProvider = dbContext.GetInfrastructure();
    var loggerFactory = serviceProvider.GetService<ILoggerFactory>();
    loggerFactory.AddProvider(new AppLoggerProvider());

    // データを取得
    var monsters = dbContext.Monsters.ToList();
    foreach (var monster in monsters) {
        Console.WriteLine($"#{monster.Id} {monster.Name}");
    }
    //#1 スライム
    //#2 ドラキー
}

実行すると次のようなログがわっさーと出てきます。ちょっと見づらいですが、コネクションを開いたり閉じたりしたログ、SELECT文を実行したログなどが確認できますね。

Compiling query model:
'from Monster <generated>_0 in DbSet<Monster>
select [<generated>_0]'
Optimized query model:
'from Monster <generated>_0 in DbSet<Monster>
select [<generated>_0]'
(QueryContext queryContext) => IEnumerable<Monster> _InterceptExceptions(
    source: IEnumerable<Monster> _TrackEntities(
        results: IEnumerable<Monster> _ShapedQuery(
            queryContext: queryContext,
            shaperCommandContext: SelectExpression:
                SELECT [m].[Id], [m].[Name]
                FROM [Monster] AS [m],
            shaper: UnbufferedEntityShaper<Monster>),
        queryContext: queryContext,
        entityTrackingInfos: { itemType: Monster },
        entityAccessors: List<Func<Monster, object>>
        {
            Func<Monster, Monster>,
        }
    ),
    contextType: ConsoleApp.AppDbContext,
    logger: DiagnosticsLogger<Query>,
    queryContext: queryContext)
Opening connection to database 'Test' on server '.'.
Opened connection to database 'Test' on server '.'.
Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='30']
SELECT [m].[Id], [m].[Name]
FROM [Monster] AS [m]
Executed DbCommand (15ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
SELECT [m].[Id], [m].[Name]
FROM [Monster] AS [m]
A data reader was disposed.
Closing connection to database 'Test' on server '.'.
Closed connection to database 'Test' on server '.'.

ログをフィルタする

このままではちょっと情報が多いので、実行されるSQLだけを確認したいという体でログをフィルタしたいと思います。

ILoggerProvider.CreateLoggerメソッドの引数にcategoryNameがあります。ログにはいくつかカテゴリがあるようで、おそらくDbLoggerCategoryで定義されているのがそれです。

ソースを見た＋試してみたところ、DbLoggerCategory.Database.CommandがSQLの実行に関係してそうです。これを使ってフィルタするには次のようなコードになるのかなと思います。

// ロガープロバイダー
public class AppLoggerProvider : ILoggerProvider {
    // ロガーを生成
    public ILogger CreateLogger(string categoryName) {
        // SQLの実行に関するログだけ出力する
        if (string.Equals(categoryName, DbLoggerCategory.Database.Command.Name)) {
            return new ConsoleLogger();
        }

        // 何も出力しないロガー
        return NullLogger.Instance;
    }

    public void Dispose() {
    }

    // ロガー
    private class ConsoleLogger : ILogger {
        public IDisposable BeginScope<TState>(TState state) => null;
        public bool IsEnabled(LogLevel logLevel) => true;

        // ログを書き込む
        public void Log<TState>(
            LogLevel logLevel, EventId eventId,
            TState state, Exception exception,
            Func<TState, Exception, string> formatter) {
            // ログをコンソールに出力
            // LogLevelとEventIdも出力してみる
            Console.WriteLine($"{nameof(logLevel)}: {logLevel}");
            Console.WriteLine($"{nameof(eventId)}: {eventId}");
            Console.WriteLine(formatter(state, exception));
            Console.WriteLine("---");
        }
    }
}

このロガーで再度実行すると次のようなログが出力されます。

logLevel: Debug
eventId: Microsoft.EntityFrameworkCore.Database.Command.CommandExecuting
Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='30']
SELECT [m].[Id], [m].[Name]
FROM [Monster] AS [m]
---
logLevel: Information
eventId: Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted
Executed DbCommand (43ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
SELECT [m].[Id], [m].[Name]
FROM [Monster] AS [m]
---
logLevel: Debug
eventId: Microsoft.EntityFrameworkCore.Database.Command.DataReaderDisposing
A data reader was disposed.
---

ILogger.Logメソッドの引数にあるLogLevelやEventIdも気になったので出力してみましたが、このパラメータを使ってフィルタしたり、出力先を変えたりすることもできそうですね。

ちなみにEventIdはRelationalEventIdで定義されています。

今回はこんなところで。