データベース操作のログ記録とインターセプト

注

EF6 以降のみ - このページで説明されている機能、API などが Entity Framework 6 で導入されました。以前のバージョンを使用している場合、一部またはすべての情報は適用されません。

Entity Framework 6 以降では、Entity Framework がデータベースにコマンドを送信するたびに、このコマンドはアプリケーションコードでインターセプトできます。これは SQL のログ記録に最も一般的に使用されますが、コマンドの変更や中止にも使用できます。

具体的には、EF には次のものが含まれます。

LINQ to SQL の DataContext.Log に似たコンテキストの Log プロパティ
ログに送信される出力の内容と書式設定をカスタマイズするメカニズム
より高い制御/柔軟性を提供するインターセプトのための低レベルの構成要素

Context Log プロパティ

DbContext.Database.Log プロパティは、文字列を受け取る任意のメソッドのデリゲートに設定できます。最も一般的には、TextWriter の "Write" メソッドに設定することで、任意の TextWriter で使用されます。現在のコンテキストによって生成されたすべての SQL は、そのライターに記録されます。たとえば、次のコードは SQL をコンソールに記録します。

using (var context = new BlogContext())
{
    context.Database.Log = Console.Write;

    // Your code here...
}

そのコンテキストに注目してください。Database.Log は Console.Write に設定されています。これは、SQL をコンソールに記録するために必要なすべてです。

いくつかの出力を見ることができるように、いくつかの単純なクエリ/挿入/更新コードを追加しましょう。

using (var context = new BlogContext())
{
    context.Database.Log = Console.Write;

    var blog = context.Blogs.First(b => b.Title == "One Unicorn");

    blog.Posts.First().Title = "Green Eggs and Ham";

    blog.Posts.Add(new Post { Title = "I do not like them!" });

    context.SaveChanges();
}

これにより、次の出力が生成されます。

SELECT TOP (1)
    [Extent1].[Id] AS [Id],
    [Extent1].[Title] AS [Title]
    FROM [dbo].[Blogs] AS [Extent1]
    WHERE (N'One Unicorn' = [Extent1].[Title]) AND ([Extent1].[Title] IS NOT NULL)
-- Executing at 10/8/2013 10:55:41 AM -07:00
-- Completed in 4 ms with result: SqlDataReader

SELECT
    [Extent1].[Id] AS [Id],
    [Extent1].[Title] AS [Title],
    [Extent1].[BlogId] AS [BlogId]
    FROM [dbo].[Posts] AS [Extent1]
    WHERE [Extent1].[BlogId] = @EntityKeyValue1
-- EntityKeyValue1: '1' (Type = Int32)
-- Executing at 10/8/2013 10:55:41 AM -07:00
-- Completed in 2 ms with result: SqlDataReader

UPDATE [dbo].[Posts]
SET [Title] = @0
WHERE ([Id] = @1)
-- @0: 'Green Eggs and Ham' (Type = String, Size = -1)
-- @1: '1' (Type = Int32)
-- Executing asynchronously at 10/8/2013 10:55:41 AM -07:00
-- Completed in 12 ms with result: 1

INSERT [dbo].[Posts]([Title], [BlogId])
VALUES (@0, @1)
SELECT [Id]
FROM [dbo].[Posts]
WHERE @@ROWCOUNT > 0 AND [Id] = scope_identity()
-- @0: 'I do not like them!' (Type = String, Size = -1)
-- @1: '1' (Type = Int32)
-- Executing asynchronously at 10/8/2013 10:55:41 AM -07:00
-- Completed in 2 ms with result: SqlDataReader

(これは、データベースの初期化が既に行われると仮定した場合の出力であることに注意してください。データベースの初期化がまだ行われていなかった場合は、新しいデータベースを確認または作成するために移行が行うすべての作業を示す出力がさらに多くなります)。

ログに記録される内容

Log プロパティが設定されると、次のすべてがログに記録されます。

さまざまな種類のコマンドの SQL。例えば：
- 通常の LINQ クエリ、eSQL クエリ、SqlQuery などのメソッドからの生クエリを含むクエリ
- SaveChanges の一部として生成された挿入、更新、および削除
- リレーションシップの読み込みクエリは、遅延読み込みによって生成されるクエリなどがあります。
パラメーター
コマンドが非同期的に実行されているかどうか
コマンドの実行が開始された日時を示すタイムスタンプ
コマンドが正常に完了したか、例外をスローして失敗したか、非同期の場合はキャンセルされたかどうか
結果値の一部の表示
コマンドの実行にかかったおおよその時間。これは、コマンドを送信して結果オブジェクトを取得するまでの時間であることに注意してください。結果を読み取る時間は含まれません。

上記の出力例を見ると、ログに記録される 4 つの各コマンドは次のとおりです。

コンテキストの呼び出しに起因するクエリ。Blogs.First
- "First" では ToString を呼び出すことができる IQueryable が提供されないため、SQL を取得する ToString メソッドはこのクエリでは機能しなかったことに注意してください
記事の遅延読み込みにより生成されたブログのクエリ
- 遅延読み込みが行われているキー値のパラメーターの詳細に注目してください
- 既定値以外に設定されているパラメーターのプロパティのみがログに記録されます。たとえば、Size プロパティは 0 以外の場合にのみ表示されます。
SaveChangesAsync の結果の 2 つのコマンド。1 つは更新で投稿タイトルを変更する場合は 1 つ、もう 1 つは新しい投稿を追加する挿入用です。
- FK プロパティと Title プロパティのパラメーターの詳細に注目してください
- これらのコマンドが非同期的に実行されていることに注意してください

さまざまな場所へのログ記録

上記のように、コンソールへのログ記録は非常に簡単です。また、さまざまな種類の TextWriter を使用して、メモリやファイルなどに簡単にログを記録できます。

LINQ to SQL に慣れている場合、LINQ to SQL では Log プロパティが実際の TextWriter オブジェクト (Console.Out など) に設定されているのに対し、EF では Log プロパティは文字列 (Console.Write や Console.Out.Write など) を受け入れるメソッドに設定されていることがわかります。その理由は、文字列のシンクとして機能できるデリゲートを受け入れることで、EF を TextWriter から分離するためです。たとえば、ログ記録フレームワークが既にあり、次のようなログ記録方法が定義されているとします。

public class MyLogger
{
    public void Log(string component, string message)
    {
        Console.WriteLine("Component: {0} Message: {1} ", component, message);
    }
}

これは、次のように EF Log プロパティにフックできます。

var logger = new MyLogger();
context.Database.Log = s => logger.Log("EFApp", s);

結果のログ記録

既定のロガーでは、コマンドがデータベースに送信される前に、コマンドテキスト (SQL)、パラメーター、および "実行中" 行にタイムスタンプが記録されます。コマンドの実行後、経過時間を含む "完了" 行がログに記録されます。

非同期コマンドの場合、非同期タスクが実際に完了、失敗、または取り消されるまで、"完了" 行はログに記録されないことに注意してください。

"完了" 行には、コマンドの種類と、実行が成功したかどうかによって異なる情報が含まれます。

成功した実行

正常に完了したコマンドの場合、出力は "Completed in x ms with result: " に続いて、結果が何であったかを示します。データリーダーを返すコマンドの場合、結果の表示は返される DbDataReader の型です。上記の update コマンドなどの整数値を返すコマンドの場合、結果はその整数です。

失敗した実行

例外をスローして失敗したコマンドの場合、出力には例外からのメッセージが含まれます。たとえば、SqlQuery を使用して存在するテーブルに対してクエリを実行すると、ログ出力は次のようになります。

SELECT * from ThisTableIsMissing
-- Executing at 5/13/2013 10:19:05 AM
-- Failed in 1 ms with error: Invalid object name 'ThisTableIsMissing'.

取り消された実行

タスクが取り消された非同期コマンドの場合、結果は例外で失敗する可能性があります。これは、基になる ADO.NET プロバイダーが取り消そうとしたときに実行されることが多いためです。これが発生せず、タスクが正常に取り消された場合、出力は次のようになります。

update Blogs set Title = 'No' where Id = -1
-- Executing asynchronously at 5/13/2013 10:21:10 AM
-- Canceled in 1 ms

ログの内容と書式設定の変更

内部では、Database.Log プロパティは DatabaseLogFormatter オブジェクトを使用します。このオブジェクトは、IDbCommandInterceptor 実装 (下記参照) を、文字列と DbContext を受け入れるデリゲートに効果的にバインドします。つまり、DatabaseLogFormatter のメソッドは、EF によるコマンドの実行の前後に呼び出されます。これらの DatabaseLogFormatter メソッドは、ログ出力を収集して書式設定し、デリゲートに送信します。

DatabaseLogFormatter のカスタマイズ

ログに記録される内容と形式を変更するには、DatabaseLogFormatter から派生し、必要に応じてメソッドをオーバーライドする新しいクラスを作成します。オーバーライドする最も一般的な方法は次のとおりです。

LogCommand – コマンドを実行する前にログに記録する方法を変更するには、これをオーバーライドします。既定では、LogCommand は各パラメーターに対して LogParameter を呼び出します。オーバーライドで同じ操作を行うか、パラメーターを異なる方法で処理することもできます。
LogResult – コマンドの実行結果のログ記録方法を変更するには、これをオーバーライドします。
LogParameter – パラメーターログの書式設定と内容を変更するには、これをオーバーライドします。

たとえば、各コマンドがデータベースに送信される前に、1 行だけログに記録するとします。これは、次の 2 つのオーバーライドで実行できます。

LogCommand をオーバーライドして SQL の 1 行を書式設定および書き込む
何も行わないよう LogResult をオーバーライドします。

コードは次のようになります。

public class OneLineFormatter : DatabaseLogFormatter
{
    public OneLineFormatter(DbContext context, Action<string> writeAction)
        : base(context, writeAction)
    {
    }

    public override void LogCommand<TResult>(
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        Write(string.Format(
            "Context '{0}' is executing command '{1}'{2}",
            Context.GetType().Name,
            command.CommandText.Replace(Environment.NewLine, ""),
            Environment.NewLine));
    }

    public override void LogResult<TResult>(
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
    }
}

出力をログに記録するには、構成された書き込みデリゲートに出力を送信する Write メソッドを呼び出すだけです。

(このコードでは、例として改行が単純に削除されることに注意してください。複雑な SQL を表示する場合は、うまく機能しない可能性があります)。

DatabaseLogFormatter の設定

新しい DatabaseLogFormatter クラスが作成されたら、EF に登録する必要があります。これは、コードベースの構成を使用して行われます。簡単に言うと、これは、DbContext クラスと同じアセンブリで DbConfiguration から派生した新しいクラスを作成し、この新しいクラスのコンストラクターで SetDatabaseLogFormatter を呼び出すことです。例えば次が挙げられます。

public class MyDbConfiguration : DbConfiguration
{
    public MyDbConfiguration()
    {
        SetDatabaseLogFormatter(
            (context, writeAction) => new OneLineFormatter(context, writeAction));
    }
}

新しい DatabaseLogFormatter の使用

この新しい DatabaseLogFormatter は、Database.Log が設定されるたびに使用されるようになります。そのため、パート 1 からコードを実行すると、次の出力が生成されます。

Context 'BlogContext' is executing command 'SELECT TOP (1) [Extent1].[Id] AS [Id], [Extent1].[Title] AS [Title]FROM [dbo].[Blogs] AS [Extent1]WHERE (N'One Unicorn' = [Extent1].[Title]) AND ([Extent1].[Title] IS NOT NULL)'
Context 'BlogContext' is executing command 'SELECT [Extent1].[Id] AS [Id], [Extent1].[Title] AS [Title], [Extent1].[BlogId] AS [BlogId]FROM [dbo].[Posts] AS [Extent1]WHERE [Extent1].[BlogId] = @EntityKeyValue1'
Context 'BlogContext' is executing command 'update [dbo].[Posts]set [Title] = @0where ([Id] = @1)'
Context 'BlogContext' is executing command 'insert [dbo].[Posts]([Title], [BlogId])values (@0, @1)select [Id]from [dbo].[Posts]where @@rowcount > 0 and [Id] = scope_identity()'

インターセプトの構成要素

ここまでは、DbContext.Database.Log を使用して EF によって生成された SQL をログに記録する方法について説明しました。しかし、このコードは実際には、より一般的なインターセプトのために、いくつかの低レベルの構成要素の上に比較的薄いファサードです。

インターセプトインタフェース

インターセプトコードは、インターセプトインターフェイスの概念を中心に構築されています。これらのインターフェイスは IDbInterceptor から継承し、EF が何らかのアクションを実行するときに呼び出されるメソッドを定義します。目的は、インターセプトされるオブジェクトの種類ごとに 1 つのインターフェイスを持つことです。たとえば、IDbCommandInterceptor インターフェイスは、EF が ExecuteNonQuery、ExecuteScalar、ExecuteReader、および関連メソッドを呼び出す前に呼び出されるメソッドを定義します。同様に、インターフェイスは、これらの各操作が完了したときに呼び出されるメソッドを定義します。上で説明した DatabaseLogFormatter クラスは、このインターフェイスを実装してコマンドをログに記録します。

インターセプトコンテキスト

インターセプターインターフェイスで定義されているメソッドを見ると、すべての呼び出しに DbInterceptionContext 型のオブジェクト、またはそこから派生した何らかの型 (DbCommandInterceptionContext<> など) が与えられていることがわかります。このオブジェクトには、EF が実行しているアクションに関するコンテキスト情報が含まれています。たとえば、アクションが DbContext に代わって実行されている場合、DbContext は DbInterceptionContext に含まれます。同様に、非同期で実行されるコマンドの場合、IsAsync フラグは DbCommandInterceptionContext に設定されます。

結果の処理

DbCommandInterceptionContext<> クラスには、Result、OriginalResult、Exception、OriginalException というプロパティが含まれています。これらのプロパティは、オペレーションが実行される前に呼び出されるインターセプトメソッド、つまり ...Executing メソッドの呼び出しに対して null またはゼロに設定されます。操作が実行され、成功した場合、Result と OriginalResult は操作の結果に設定されます。これらの値は、操作が実行された後に呼び出されるインターセプションメソッド、つまり...Executedメソッドで確認できます。同様に、操作が例外をスローすると、Exception プロパティと OriginalException プロパティが設定されます。

実行の抑制

インターセプターが、コマンドが実行される前に Result プロパティを設定した場合 (...メソッドの実行)、EF は実際にコマンドを実行しようとせず、代わりに結果セットを使用します。つまり、インターセプターはコマンドの実行を抑制できますが、コマンドが実行されたかのように EF を続行できます。

これを使用する方法の例として、従来はラッピングプロバイダーで実行されていたコマンドバッチ処理があります。インターセプターは、後で実行するためにコマンドをバッチとして格納しますが、コマンドが通常どおりに実行されたことを EF に "ふり" します。バッチ処理を実装するにはこれ以上のものが必要ですが、これはインターセプト結果を変更する方法の例です。

実行は、ある …Executingメソッドで Exception プロパティを設定することによって抑制されることもあります。これにより、指定された例外をスローして操作の実行が失敗したかのように EF が続行されます。これはもちろん、アプリケーションがクラッシュする可能性がありますが、EF によって処理される一時的な例外またはその他の例外である可能性もあります。たとえば、これをテスト環境で使用して、コマンドの実行が失敗した場合のアプリケーションの動作をテストできます。

実行後の結果の変更

インターセプターが、コマンドの実行後に Result プロパティを設定する場合 (...実行されたメソッド)、EF は、操作から実際に返された結果ではなく、変更された結果を使用します。同じように、コマンドが実行された後にインターセプターによって Exception プロパティが設定された場合、EF は、操作が例外をスローしたかのように設定された例外をスローします。

インターセプターは Exception プロパティを null に設定して、例外をスローできないことを示すこともできます。これは、操作の実行が失敗したが、インターセプターが操作が成功したかのように EF を続行したい場合に役立ちます。これは通常、結果を設定して、EF が作業を続けるための結果値を持てるようにすることも含まれます。

OriginalResult と OriginalException

EF は操作を実行した後、実行が失敗しなかった場合は Result プロパティと OriginalResult プロパティを設定し、例外で実行が失敗した場合は Exception プロパティと OriginalException プロパティを設定します。

OriginalResult プロパティと OriginalException プロパティは読み取り専用であり、操作を実際に実行した後にのみ EF によって設定されます。これらのプロパティはインターセプターでは設定できません。つまり、インターセプターは、実際の例外や操作の実行時に発生した結果とは対照的に、他のインターセプターによって設定された例外または結果を区別できます。

インターセプターの登録

1 つ以上のインターセプトインターフェイスを実装するクラスが作成されたら、DbInterception クラスを使用して EF に登録できます。例えば次が挙げられます。

DbInterception.Add(new NLogCommandInterceptor());

インターセプターは、DbConfiguration コードベースの構成メカニズムを使用して、アプリドメインレベルで登録することもできます。

例: NLog へのログ記録

これらすべてを、IDbCommandInterceptor と NLog を使用して次の操作を行う例にしましょう。

非同期に実行されていないコマンドの警告をログに記録する
実行時に例外を投げる任意のコマンドのエラーをログに記録する

ログ記録を行うクラスを次に示します。これは、上記のように登録する必要があります。

public class NLogCommandInterceptor : IDbCommandInterceptor
{
    private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

    public void NonQueryExecuting(
        DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
        LogIfNonAsync(command, interceptionContext);
    }

    public void NonQueryExecuted(
        DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
        LogIfError(command, interceptionContext);
    }

    public void ReaderExecuting(
        DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        LogIfNonAsync(command, interceptionContext);
    }

    public void ReaderExecuted(
        DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        LogIfError(command, interceptionContext);
    }

    public void ScalarExecuting(
        DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        LogIfNonAsync(command, interceptionContext);
    }

    public void ScalarExecuted(
        DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        LogIfError(command, interceptionContext);
    }

    private void LogIfNonAsync<TResult>(
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        if (!interceptionContext.IsAsync)
        {
            Logger.Warn("Non-async command used: {0}", command.CommandText);
        }
    }

    private void LogIfError<TResult>(
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        if (interceptionContext.Exception != null)
        {
            Logger.Error("Command {0} failed with exception {1}",
                command.CommandText, interceptionContext.Exception);
        }
    }
}

このコードでは、インターセプトコンテキストを使用して、コマンドが非同期以外で実行されているタイミングを検出し、コマンドの実行中にエラーが発生したことを検出する方法に注目してください。

フィードバック

このページはお役に立ちましたか?

Last updated on 2026-03-27