データベース操作のログ記録とインターセプト
Note
EF6 以降のみ - このページで説明する機能、API などは、Entity Framework 6 で導入されました。 以前のバージョンを使用している場合、一部またはすべての情報は適用されません。
Entity Framework 6 以降、Entity Framework からデータベースにコマンドを送信するときはいつでも、このコマンドをアプリケーション コードからインターセプトできるようになりました。 これは SQL のログを記録するために最もよく使用しますが、コマンドを変更または中止するために使用することもできます。
具体的には、EF には以下のものが用意されています。
- LINQ to SQL の DataContext.Log に似たコンテキスト用 Log プロパティ
- ログに送信される出力の内容と書式設定をカスタマイズするメカニズム
- より優れた制御と柔軟性を提供する、インターセプトに対する低レベルの構成要素
コンテキストの Log プロパティ
DbContext.Database.Log プロパティは、文字列を受け取る任意のメソッドのデリゲートに設定できます。 最も一般的なのは、任意の TextWriter で使用することで、その TextWriter の "Write" メソッドに設定します。 現在のコンテキストによって生成されたすべての SQL が、そのライターにログ記録されます。 たとえば、次のコードを使用して、SQL をコンソールにログ記録します。
using (var context = new BlogContext())
{
context.Database.Log = Console.Write;
// Your code here...
}
context.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 つのコマンドはそれぞれ次のとおりです。
- context.Blogs.First の呼び出しから生成されるクエリ
- "First" では ToString を呼び出すことができる IQueryable が提供されないため、SQL を取得する ToString メソッドが、このクエリでは機能しないことに注意してください
- blog.Posts の遅延読み込みから生成されるクエリ
- 遅延読み込みが発生しているキー値のパラメーターの詳細に注目します
- 既定値以外に設定されているパラメーターのプロパティだけがログに記録されています。 たとえば、Size プロパティは、0 以外の場合にのみ表示されます。
- SaveChangesAsync から生成される 2 つのコマンド。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)、パラメーター、および "Executing" 行がタイムスタンプ付きでログに記録されます。 コマンドの実行後、経過時間を含む "完了" 行がログに記録されます。
非同期コマンドの場合は、"完了" 行が、非同期タスクが実際に完了、失敗、または取り消されるまでログに記録されないことに注意してください。
"完了" 行には、コマンドの種類と、実行が成功したかどうかに応じて異なる情報が含まれます。
実行が成功
コマンドが正常に完了した場合、出力には、"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 オブジェクトが利用されます。 このオブジェクトにより、文字列と DbContext を受け取るデリゲートに IDbCommandInterceptor 実装 (後述) が効果的にバインドされます。 つまり、DatabaseLogFormatter のメソッドは、EF によるコマンドの実行の前と後に呼び出されます。 これらの DatabaseLogFormatter メソッドによって、ログ出力が収集および書式設定され、デリゲートに送信されます。
DatabaseLogFormatter のカスタマイズ
ログに記録される内容と書式設定の方法を変更するには、DatabaseLogFormatter から派生し、必要に応じてメソッドをオーバーライドする新しいクラスを作成します。 最もよくオーバーライドするのは、次のメソッドです。
- LogCommand – コマンドの実行前にログに記録される方法を変更するには、これをオーバーライドします。 LogCommand の既定では、パラメーターごとに LogParameter が呼びされます。代わりに、オーバーライドで同じことを行うか、パラメーターを異なる方法で処理するかを選択できます。
- LogResult – コマンドの実行結果がログに記録される方法を変更するには、これをオーバーライドします。
- LogParameter – パラメーター ログの書式設定と内容を変更するには、これをオーバーライドします。
たとえば、各コマンドがデータベースに送信される前に、1 行だけログを記録したいとします。 これは、次の 2 つのオーバーライドで実行できます。
- 1 行の SQL を書式設定して書き込むように LogCommand をオーバーライドする
- 何も行わないように 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 または 0 に設定されます。 操作が実行され、成功すると、Result と OriginalResult は操作の結果に設定されます。 これらの値は、操作の実行後に呼び出されるインターセプト メソッド、つまり、…Executed メソッドで確認できます。 同様に、操作で例外がスローされると、Exception および OriginalException プロパティが設定されます。
実行の抑制
コマンドの実行前に (…Executing メソッドの 1 つで) インターセプターで Result プロパティを設定した場合、EF では、そのコマンドの実行は実際には試行されず、代わりに単に結果セットが使用されます。 つまり、インターセプターでコマンドの実行を抑制して、そのコマンドが実行されたかのように EF を続行させることができます。
これが使用される可能性がある例としては、従来はラッピング プロバイダーで実行されてきたコマンドバッチ処理があります。 インターセプターで、後で実行するコマンドをバッチとして格納しますが、コマンドが通常どおり実行されたように EF に "見せかけ" ます。 バッチ処理を実装するにはこれ以外にも処理が必要であり、これはインターセプトの結果の変更を使用する一例にすぎないことに注意してください。
また、…Executing メソッドの 1 つで Exception プロパティを設定して、実行を抑制することもできます。 こうすると、EF で、指定した例外がスローされ、操作の実行が失敗したかのように続行します。 もちろん、この結果、アプリケーションがクラッシュする場合もありますが、一時的な例外、または EF によって処理されるその他の例外の場合もあります。 たとえば、これをテスト環境で使用すると、コマンド実行失敗時のアプリケーションの動作をテストすることができます。
実行後の結果の変更
コマンドの実行後に (…Executed メソッドの 1 つで) インターセプターで Result プロパティを設定した場合、EF では、実際に操作から返された結果ではなく、変更された結果が使用されます。 同様に、コマンドの実行後にインターセプターで Exception プロパティを設定した場合、EF で、操作によって例外がスローされたかのように、設定した例外がスローされます。
また、インターセプターで、Exception プロパティを null に設定して、例外をスローする必要がないことを示すこともできます。 これは、操作の実行が失敗したが、インターセプターで、操作が成功したかのように EF を続行させたい場合に便利です。 通常は、これにより、EF が続行するときに処理する何らかの結果値を持つように Result も設定されます。
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);
}
}
}
このコードで、インターセプト コンテキストを使用して、コマンドがいつ非同期に実行されているのかを検出し、コマンドの実行時にいつエラーがあったかを検出している方法に注目してください。
.NET