ツナ缶雑記

ぐうたらSEのブログです。主にマイクロソフト系技術を中心に扱います。

Entity Framework 6で実行したSQLと実行時間をアプリケーション内で取得する方法

Entity Frameworkを使用すると、特にSQLを意識しなくても、データアクセス処理を実装することができてしまいます。その反面、実際にどのようなクエリが流れているのか、そしてそのクエリの実行にどのくらいの時間がかかっているのかを後から知ろうとすると、SQL Profilerなどを使ってデータベース側で監視する必要があります。これをもうちょっとお手軽にアプリケーション側で測定する方法を書いてみます。

環境

Entity Frameworkのインターセプターを実装する

Entity Frameworkには、SQLクエリを実行する前後に処理を差し込むためのインターセプターという仕組みが存在します。この仕組みを用いることで、実際に実行したクエリや、その実行時間を記録することができるようになります。インターセプターは、System.Data.Entity.Infrastructure.Interception.IDbCommandInterceptor を実装して、アプリケーションコードまたは構成ファイルを通して適用することで利用できるようになります。今回は構成ファイルを用いて適用する方法を書いてみます。

さて、IDbCommandInterceptorは、以下のようなインターフェースを持っています。

public interface IDbCommandInterceptor : IDbInterceptor
{
    void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext);
    void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext);
    void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext);
    void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext);
    void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext);
    void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext);
}

XXingという名前のメソッドが、SQLクエリを実行する前に差し込まれる処理で、XXedという名前のメソッドが、SQLクエリが実行された後に差し込まれる処理です。実行するSQLクエリの種類に応じて、3つのペアのうちどれかが実行されます。

  • NonQueryExecute系
    • DDLの実行やINSERT, UPDATE, DELETEなどの処理を実行したときに呼び出されます
    • ただし、INSERT, UPDATE, DELETEを行った後SELECTが内部的に実行される場合は、ReaderExecute系が動作します
  • ReaderExecute系
    • データリーダーを用いるSELECT処理を実行したときに呼び出されます
    • 表形式のデータを取得する処理で呼び出されます
  • ScalarExecute系
    • COUNTなどの集計関数を用いるSELECT処理を実行したときに呼び出されます

上記の前提を踏まえて、IDbCommandInterceptorを実装したクラスに対して、ログ出力処理を組み込んでみます。今回はことを簡単にするため、以下の条件で実装していますので、コピペする際はご注意ください。

  • 例外処理はそれほど考えてありませんし、条件によっては動作しないケースがあるかもしれません
  • ログ出力は処理が完了したタイミングで、Traceに対して実行します
  • ログには以下の項目を含めます
    • 実行したSQLクエリ
    • そのクエリに対してアプリケーションから与えたパラメーター
    • SQLクエリの実行に要した時間
    • 例外が発生してる場合、その例外の情報

この条件で、実装すると以下のようになります。

using System;
using System.Collections.Concurrent;
using System.Collections.Generic;
using System.Data.Common;
using System.Data.Entity.Infrastructure.Interception;
using System.Diagnostics;

namespace SampleClassLib.Data
{
    public class DBLogInterceptor : IDbCommandInterceptor
    {
        private static readonly ConcurrentDictionary<DbCommand, Stopwatch> StopwatchList = new ConcurrentDictionary<DbCommand, Stopwatch>();

        public void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
        {
            long? elapsedTime = StopStopWatch(command);
            WriteLog(command, elapsedTime, interceptionContext.Exception);
        }

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

        public void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
        {
            long? elapsedTime = StopStopWatch(command);
            WriteLog(command, elapsedTime, interceptionContext.Exception);
        }

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

        public void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
        {
            long? elapsedTime = StopStopWatch(command);
            WriteLog(command, elapsedTime, interceptionContext.Exception);
        }

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

        private static void WriteLog(DbCommand command, long? elapsedTime, Exception ex)
        {
            List<string> parameters = new List<string>();
            foreach (DbParameter parameter in command.Parameters)
            {
                parameters.Add($"\"{parameter.ParameterName}\":\"{parameter.Value}\"");
            }

            if (ex != null)
            {
                Trace.WriteLine($"【Error!!】実行時間:{elapsedTime}ms, 実行コマンド:{command.CommandText}, パラメーター:{{{string.Join(",", parameters)}}}, 例外情報:{ex.ToString()}");
            }
            else
            {
                Trace.WriteLine($"実行時間:{elapsedTime}ms, 実行コマンド:{command.CommandText}, パラメーター:{{{string.Join(",", parameters)}}}");
            }
        }

        private void StartStopWatch(DbCommand command)
        {
            if (command == null)
            {
                return;
            }

            Stopwatch stopwatch = Stopwatch.StartNew();
            StopwatchList.TryAdd(command, stopwatch);
        }

        private long? StopStopWatch(DbCommand command)
        {
            if (command == null)
            {
                return null;
            }

            if (StopwatchList.TryRemove(command, out Stopwatch stopwatch))
            {
                stopwatch.Stop();
                return stopwatch.ElapsedMilliseconds;
            }

            return null;
        }
    }
}

なお今回は、このクラスをログ出力させたい本体のアプリケーションとは、まったく別のクラスライブラリプロジェクトに実装しておきましょう。このクラスを含むクラスライブラリを単体でビルドして、DLLを作っておきましょう。これで準備が整いました。

アプリケーション本体への組み込み

作成したDLLを、ログ出力を行いたいアプリケーション本体に組み込むには、アプリケーションの実行ディレクトリに、作成したDLLを配置し、構成ファイルに設定を記載することになります。本体のアプリケーションの設定変更や、参照の追加などは必要ありません。

Webアプリケーションの場合は、ルートディレクトリの直下にあるbinディレクトリ内に、コンソールアプリケーションなどの実行ファイルを持つアプリケーションの場合は、EXEファイルと同じディレクトリ内にビルドしたDLLを配置します。

f:id:masatsuna:20190717231502p:plain
Webアプリケーションの場合

f:id:masatsuna:20190717231649p:plain
実行ファイルを持つアプリケーションの場合

今回作成したDLLは「SampleClassLib.Data.dll」という名前のDLLです。これを、各実行ディレクトリに配置すると、上記のようになります。

構成ファイルの設定

続いて、構成ファイルの設定を変更していきます。Webアプリケーションの場合は、ルートディレクトリにあるWeb.configを、実行ファイルを持つアプリケーションの場合は、実行ディレクトリ内に存在する「<実行ファイルの名前>.exe.config」が構成ファイルになります。これらのファイルをエディターで開き、設定を追加します。

今回作成したインターセプターは、System.Diagnostics.Trace クラスを用いてログ出力を行うよう実装しています。ですので、まずはTraceクラスが使用するトレースリスナーの設定を行います。Traceクラスにトレースリスナーを登録するには、構成ファイルの<system.diagnostics>セクション<trace>/<listeners>要素に<add>要素を追加して、トレースリスナーの型と、その設定を記載します。例えばファイル出力を行うための設定例は以下のようになります。この状態でTraceクラスを呼び出すと、ルートディレクトリにDataAccess.logという名前のログファイルが出力され、ログが記録されるようになります。

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <!-- 他の設定値は省略 -->
  <system.diagnostics>
    <trace autoflush="true">
      <listeners>
        <add name="file" type="System.Diagnostics.TextWriterTraceListener" initializeData="DataAccess.log"  />
      </listeners>
    </trace>
  </system.diagnostics>
</configuration>

なおトレースリスナーは既定でいくつか別の実装もあります。今回はファイル出力する例を用いていますが、コンソール画面に出力させたり、イベントログに出力させたりすることもできます。またトレースリスナーを複数登録すると、同じログを複数の場所に出力することもできます。.NET Frameworkに標準で準備されているトレースリスナーは、以下を参照してください。TraceListenerクラスの派生クラスが、使用可能なトレースリスナーです。

docs.microsoft.com

続いて、作成したインターセプターを登録します。インターセプターは、<entityFramework>セクション<interceptors>要素に<interceptor>要素を追加して、作成したインターセプターの型を記載します。今回はSampleClassLib.Data.dllにあるSampleClassLib.Data.DBLogInterceptorクラスを登録するので、以下のように設定します。

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <configSections>
    <section name="entityFramework" type="System.Data.Entity.Internal.ConfigFile.EntityFrameworkSection, EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" requirePermission="false" />
  </configSections>
  <!-- 他の設定値は省略 -->
  <entityFramework>
    <!-- 他の設定値は省略 -->
    <interceptors>
      <interceptor type="SampleClassLib.Data.DBLogInterceptor, SampleClassLib.Data"></interceptor>
    </interceptors>
  </entityFramework>
</configuration>

このようにすることで、Entity Frameworkを用いてデータアクセスを行うと、作成したインターセプターが動作して、ログ出力が行われます。

まとめ

今回はEntity Frameworkのインターセプターという仕組みを用いて、Entity Frameworkを通して実行したSQLクエリと、その実行時間をログ出力する方法を書きました。今回紹介した方法だと、本体のアプリケーションコードを変更することなく、後からログ出力機能をわずかな設定変更のみで適用することができます。またログ出力を行いたいプロジェクトから、インターセプターを実装したクラスが含まれるDLLに対して参照を追加する必要もありません。コード修正ができないケースでも使える方法ですので、参考にしてみてください。