データベース操作のログ記録と受信

注意

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

Entity Framework 6 以降では、Entity Framework は常にコマンドをデータベースに送信します。このコマンドは、アプリケーションコードによって傍受される可能性があります。 これは、SQL をログ記録するために最も一般的に使用されますが、コマンドを変更または中止するために使用することもできます。

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

  • DataContext と同様のコンテキストのログプロパティ LINQ to SQL
  • ログに送信される出力の内容と書式をカスタマイズするためのメカニズム
  • インターセプトのための低レベルの構成ブロックにより、制御性と柔軟性が向上

コンテキストログのプロパティ

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

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

    // Your code here...
}

コンテキストに注意してください。データベース .Log は、Console. 書き込みに設定されています。 これは、コンソールに 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.SaveChangesAsync().Wait();
}

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

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つのコマンドがログに記録されます。

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

別の場所へのログ記録

前述のように、コンソールへのログ記録はとても簡単です。 また、異なる種類の TextWriterを使用して、メモリやファイルなどに簡単にログを記録することもできます。

LINQ to SQL を使い慣れている場合は、LINQ to SQL で log プロパティが実際の TextWriter オブジェクト (たとえば、console. out) に設定されていることに気付くかもしれませんが、EF では、log プロパティは文字列を受け入れるメソッドに設定されています (たとえば、write または console)。 これは、文字列のシンクとして機能するデリゲートを受け入れることによって、TextWriter から EF を分離するためです。 たとえば、既にいくつかのログ記録フレームワークがあり、次のようなログ記録方法が定義されているとします。

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);

結果のログ記録

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

非同期コマンドの場合、非同期タスクが実際に完了、失敗、またはキャンセルされるまで、"completed" 行は記録されません。

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

成功した実行

正常に完了したコマンドの場合、出力は "x ミリ秒で完了しました。結果:" の後に結果を示すいくつかの結果が続きます。 データリーダーを返すコマンドの場合は、返される 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

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

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

DatabaseLogFormatter のカスタマイズ

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

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

たとえば、各コマンドがデータベースに送信される前に1行だけログを記録したいとします。 これは、次の2つの上書きを使用して行うことができます。

  • LogCommand をオーバーライドして SQL の単一行を書式設定して書き込む
  • 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)
    {
    }
}

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

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

DatabaseLogFormatter の設定

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

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

新しい DatabaseLogFormatter の使用

この新しい DatabaseLogFormatter は、いつでもデータベース .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 を使用して、EF によって生成された SQL をログに記録する方法を見てきました。 しかし、このコードは実際には、より一般的なインターセプトを行うために、一部の低レベルの構成要素に対して比較的シンファサードです。

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

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

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

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

結果の処理

DbCommandInterceptionContext クラスには <> 、Result、OriginalResult、Exception、OriginalException というプロパティが含まれている。 これらのプロパティは、操作が実行される前に呼び出されるインターセプト メソッドの呼び出し (... の場合) に対して null/0 に設定されます。メソッドの実行。 操作が実行され、成功した場合、Result と OriginalResult は操作の結果に設定されます。 これらの値は、操作の実行後に呼び出されるインターセプト メソッド (つまり、 で) で観察できます。実行されたメソッド。 同様に、操作がスローされた場合は、Exception プロパティと OriginalException プロパティが設定されます。

実行の抑制

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

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

実行を抑制するには、 の 1 つで 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);
        }
    }
}

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