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

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

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

EF Core | Microsoft Docs

ログを出力する

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

// ロガープロバイダー
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.CommandSQLの実行に関係してそうです。これを使ってフィルタするには次のようなコードになるのかなと思います。

// ロガープロバイダー
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メソッドの引数にあるLogLevelEventIdも気になったので出力してみましたが、このパラメータを使ってフィルタしたり、出力先を変えたりすることもできそうですね。

ちなみにEventIdRelationalEventIdで定義されています。

今回はこんなところで。

Entity Framework Coreはじめました

EF Coreを試しはじめました。先はあまり考えていませんが、色々試したことを書き残していけるといいなと思います。とりあえず今回は最初なのでSQL Serverにあるデータを取得してみます。

データの用意

まずはSQL Server Management Studioでデータを用意しておきます。

-- テーブルを作る
drop table if exists dbo.Monster;
create table dbo.Monster(
    Id int,
    Name nvarchar(20),
    constraint PK_Monster primary key(Id)
);

-- データを投入
insert into dbo.Monster(Id, Name)
output inserted.*
values
    (1, N'スライム'),
    (2, N'ドラキー');
/*
Id          Name
----------- --------------------
1           スライム
2           ドラキー
*/

EF Coreのインストール

ここからはVisual Studioです。.NET Coreのコンソールアプリプロジェクトを作成してNugetで必要なものを取得しましょう。パッケージマネージャーコンソールで以下を実行です。

Install-Package Microsoft.EntityFrameworkCore.SqlServer

エンティティとDBコンテキストの用意

エンティティとDBコンテキストを用意します。

EF6とは違って接続文字列はOnConfiguringメソッド内で指定するみたいです。

個人的な好みでテーブル名は単数形にしたいのですが、EF6にあったPluralizingTableNameConventionのようなクラスはどうもなさそうな?(しっかり調べていない)ので、愚直にToTableメソッドでエンティティをテーブルにマッピングしています。

// エンティティ
public class Monster {
    public int Id { get; set; }
    public string Name { get; set; }
}

// DBコンテキスト
public class AppDbContext : DbContext {
    public DbSet<Monster> Monsters { get; set; }

    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder) {
        // 接続文字列を指定する
        var connectionString = new SqlConnectionStringBuilder {
            DataSource = ".",
            InitialCatalog = "Test",
            IntegratedSecurity = true,
        }.ToString();
        optionsBuilder.UseSqlServer(connectionString);
    }

    protected override void OnModelCreating(ModelBuilder modelBuilder) {
        // テーブルにマッピングする
        modelBuilder.Entity<Monster>().ToTable("Monster");
    }
}

データの取得

データを取得してみます。このあたりはEF6と同じですね。

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

次の環境で確認しています。

今回はこのへんで。

参考

FORMATMESSAGE関数を試す

SQL Server 2016からFORMATMESSAGE関数が拡張されて、プレイスホルダーを使って文字列を組み立てられるようになりました。

FORMATMESSAGE (Transact-SQL) | Microsoft Docs

C言語のprintfみたい感じですかね。たぶん。

文字列を埋め込むには%sを使います。

-- 文字列を埋め込む
print formatmessage(N'Hello, %s!', N'World');

/*
Hello, World!
*/

数字の埋め込みには%d%u%xなどを使います。

-- 整数を埋め込む
print formatmessage(N'Hello, %d!', 1);

/*
Hello, 1!
*/

-- 符号なし整数、符号なし16進数を埋め込む
declare @value int = 10;
print formatmessage(N'10進数 %u => 16進数 %x', @value, @value);

/*
10進数 10 => 16進数 a
*/

詳しい書式の説明は、こちらのRAISERROR関数のドキュメントにあります。

RAISERROR (Transact-SQL) | Microsoft Docs

STRING_SPLIT関数で文字列を分割する

SQL Server 2016から使えるSTRING_SPLIT関数を試してみます。

STRING_SPLIT (Transact-SQL) | Microsoft Docs

この関数は1つ目の引数の文字列を2つ目の引数の文字で分割します。戻り値はvalueカラムを1つだけ持つ表形式の結果セットです。

-- ','で分割する
select *
from string_split(N'abc,def,ghi', N',');

-- 結果
/*
value
-----------
abc
def
ghi
*/

1つ目の引数がnullの場合、戻り値は空の結果セット(レコードが0件)になります。分割できない場合は、引数の値がそのまま返ってきます。

-- 引数がnullの場合は空の結果セット
select *
from string_split(null, N',');
/*
value
-----
*/

-- 引数が分割できない場合は引数の値
select *
from string_split(N'abc', N',');
/*
value
-----
abc
*/

また2つ目の引数に文字を複数指定するとエラーになります。

-- エラーになる
select *
from string_split(N'abc_def-ghi', N'_-');

/*
プロシージャでは型 'nchar(1)/nvarchar(1)' のパラメーター 'separator' を想定しています。
*/

SQL Server - 拡張イベントを使ってスロークエリを取得するクエリ(ファイル編)

前の記事では、拡張イベントを使ってスロークエリを取得しつつ次の2つのクエリを書いてみました。

  • ターゲットにリングバッファ(メモリ)を指定してセッションを作成するクエリ
  • リングバッファに出力されたイベントデータを確認するクエリ

ichiroku11.hatenablog.jp

拡張イベントではターゲット(=イベントデータの出力先)にファイルも指定できます。ファイルを使ったクエリを前回と同じように書き残しておきたいと思います。

ターゲットにファイルを指定してセッションを作成するクエリ

add target句でターゲットにpackage0.event_fileを指定し、さらにパラメータとして出力先のファイルパスを指定します。それ以外は前回と同じクエリです。

-- イベントセッションを作成
create event session test_xes
    on server
    -- sql_batch_completedイベントをキャプチャする
    add event sqlserver.sql_batch_completed(
        -- duration(バッチが完了するまでの時間)が3秒以上のイベントにフィルタする
        where duration >= 3000000
    ),
    -- rpc_completedイベントをキャプチャする
    add event sqlserver.rpc_completed(
        where duration >= 3000000
    )
    -- イベントデータをファイルに出力する
    add target package0.event_file(
        -- 出力先のファイルパスを指定する
        set filename = N'C:\Temp\test_xes.xel'
    );

実際には出力先のファイル名の末尾に_0_{数字}がつきます。

-- こんな感じのファイル名になる
test_xes_0_131475877870900000.xel

ファイルに出力されたイベントデータを確認するクエリ

まずファイルを読み込むにはsys.fn_xe_file_target_read_file関数を使います。関数が返す結果セットのevent_dataカラムからイベントデータを取得できるので、あとはXQueryを使って何とかします。

with xe_e(data)
as(
    select cast(event_data as xml) -- データ
    -- ファイルを読み込む
    from sys.fn_xe_file_target_read_file(N'C:\Temp\test_xes_*.xel', null, null, null)
)
select
    data.value('(event/@package)[1]', 'nvarchar(10)') as package,
    data.value('(event/@name)[1]', 'nvarchar(20)') as event,
    data.value('(event/@timestamp)[1]', 'datetime2') as timestamp,
    data.value('(event/data[@name="duration"]/value)[1]', 'bigint') as duration,
    data.value('(event/data[@name="batch_text"]/value)[1]', 'nvarchar(max)') as batch_text,
    data.value('(event/data[@name="statement"]/value)[1]', 'nvarchar(max)') as statement
from xe_e;

-- 結果は前回と同じなので省略

参考