SQLログの取得

概要

DBFluteで実行されたSQLは、全てデバッグログに表示用SQLとして出力されますが、そのログをアプリで取得することができます。例えば、本番環境において操作ログの一環として実行されたSQLをログに残すというような場合、 (ログレベルはデバッグはOFFの状態でも)取得したログを操作ログ専用のファイルに出力するというようなことができます。

ただ、表示用SQLだけを取得して単にログに出力したいのであれば、Log4j で QLog クラスで出力されるログだけを有効にする設定をすれば、表示用SQLだけログに出力するという要件は実現できます。ただし、それだと小回りが利きにくいため、細かい制御をするに場合はこの "SQLログの取得" が有効です。

DBFluteのSQL実行ログ

基本的な使い方

SqlLogHandler

SQLログを取り扱うコールバック、SqlLogHandler をスレッドローカルに登録することで、SQL実行直前のタイミングでSQLログを取得することができます。

e.g. SqlLogHandlerの基本的な使い方 @Java
CallbackContext.setSqlLogHandlerOnThread(new SqlLogHandler() {
    public void handle(SqlLogInfo sqlLogInfo) {
        // you can handle the SQL here
        String executedSql = sqlLogInfo.getExecutedSql();
        Object[] bindArgs = sqlLogInfo.getBindArgs();
        Class<?>[] bindArgs = sqlLogInfo.getBindArgTypes();
        String displaySql = sqlLogInfo.getDisplaySql();
    }
});

try> {
    memberBhv.selectList(cb); // called it back (first)
    memberBhv.update(member); // called it back (second)
} finally {
    CallbackContext.clearSqlLogHandlerOnThread();
}

個別個別のDBアクセス処理に対して SqlLogHandler を設定するというのはあまり想定されません。実務的には、共通部分で SqlLogHandler を設定し、全てのリクエストで実行されるSQLを記録するなどの使い方が想定されます。

this - ケースごとの使い方

SqlLogInfoの属性

SqlLogInfoの属性は以下の通りです。

executedSql: 実行されたSQL。バインド変数部分は "?" はてなに
args: バインド変数の値の配列。
argTypes: バインド変数の値の型の配列。
displaySql: 表示用SQL。デバッグログに出力されているものと同じ

displaySql は、getDisplaySql() の最初の呼び出しで生成されます。その後の呼び出しではキャッシュされた文字列が戻ります(@since 0.9.9.4A)。これは、displaySql を利用しない場合に無駄な文字列生成コストを発生させないためです。ログレベルがデバッグだったりなど、別の機能で既に displaySql の文字列が存在する場合は、最初からキャッシュされています。

旧バージョンにおいて

0.9.9.0B より前のバージョンでは setSqlLogHandlerOnThread() メソッドがないため、CallbackContext を new して、setCallbackContextOnThread() を利用します。

0.9.9.4A より前のバージョンではコールバックの引数が SqlLogInfo ではなく、SqlLogInfoの属性がそのまま引数となっています。アップグレード時にはコンパイルエラーとして検知されます。

ケースごとの使い方

リクエストで実行される全てのSQLを記録

実務的には、リクエスト処理で実行されたSQL(例外になったものも含む)を全て取得して記録に残すというような要件が想定されます。その場合は、SqlLogHandler を設定する処理をリクエストの入り口で実行される Interceptor などで実装すると良いでしょう。SqlLogHandler はSQLが実行される直前にコールバックされますので、当然実行エラー(になる予定の)のSQLでもコールバックされます。

e.g. SqlLogHandler を Interceptor で登録し、全てのSQLを記録 @Java
public Object invoke(MethodInvocation invocation) throws Throwable {
    if (CallbackContext.isExistSqlLogHandlerOnThread()) {
        // 既に設定されていたら何もしないで次へ
        // (二度呼び出しされたときのために念のため)
        return invocation.proceed();
    }
    CallbackContext.setSqlLogHandlerOnThread(new SqlLogHandler() {
        public void handle(SqlLogInfo sqlLogInfo) {
            // ログに出力するなり好きなように
            ...
        }
    });

    try> {
        return invocation.proceed();
    } finally {
        // 最後はしっかりクリアすること (必須)
        CallbackContext.clearSqlLogHandlerOnThread();
    }
}

コールバックされるたびにつどつど処理するのではなく、そのリクエストのSQLをまとめて一気に処理したい場合は、コールバックでは一旦リストなどにSQLを登録して保持しておいて、リクエストが終わった後(例外時も含む)にまとめて記録すると良いでしょう。

e.g. リクエストが終わった後にまとめて記録 @Java
public Object invoke(MethodInvocation invocation) throws Throwable {
    ... // 既に設定されていたらのチェック

    final List<String> sqlList = new ArrayList<String>(); 
    CallbackContext.setSqlLogHandlerOnThread(new SqlLogHandler() {
        public void handle(SqlLogInfo sqlLogInfo) {
            sqlList.add(displaySql);
        }
    });

    try> {
        return invocation.proceed();
    } finally {
        // 最後はしっかりクリアすること (必須)
        CallbackContext.clearSqlLogHandlerOnThread();

        for (String displaySql : sqlList) {
            // ログに出力するなり煮るなり
        }
        // 厳密には、このSQLログの処理で例外が発生した場合に、
        // どういったリカバリをするか検討する必要がある。
        // (例えば、警告ログだけ出力してSQLログの例外は無視するとか)
    }
}

つどつど記録するか、まとめて記録するかは、パフォーマンス要件や記録処理のトランザクションなどの仕組み上の都合などが絡むため、そのときの要件に合わせて実装すると良いでしょう。

つどつど記録: 途中で finally コードも処理できないレベルのシステム中断が発生しても、そこまでの記録は残る。また、実装は非常に簡単になる。ただし、つどつど処理となるため、パフォーマンス上の問題が発生しやすい。
まとめて記録: 一つのリクエストに付き記録処理が必ず一つとなるので、パフォーマンス上の問題やトランザクションなど記録処理の仕組みの都合などは比較的回避しやすいと想定される。ただし、途中で finally コードも処理できないレベルのシステム中断が発生した場合には何も残らない。; また、一つのリクエストでSQLを(例えば)10万回以上実行するような処理があった場合、10万のSQLが一時的にリストに登録されるため、メモリを圧迫する可能性がある。

例外中断したリクエストのSQLを記録

例外で中断したリクエストで実行されたSQLだけを記録したい場合は、コールバックでは一旦リストなどにSQLを登録して保持しておいて、例外が発生したときにだけ記録すると良いでしょう。

e.g. 例外中断したリクエストのSQLを記録 (Interceptor利用) @Java
public Object invoke(MethodInvocation invocation) throws Throwable {
    ... // 既に設定されていたらのチェック

    final List<String> sqlList = new ArrayList<String>(); 
    CallbackContext.setSqlLogHandlerOnThread(new SqlLogHandler() {
        public void handle(SqlLogInfo sqlLogInfo) {
            sqlList.add(sqlLogInfo.getDisplaySql());
        }
    });
    CallbackContext.setCallbackContextOnThread(context);

    try> {
        return invocation.proceed();
    } catch (Exception e) {
        for (String displaySql : sqlList) {
            // ログに出力するなり煮るなり
        }
        // 厳密には、このSQLログの処理で例外が発生した場合に、
        // どういったリカバリをするか検討する必要がある。
        // (例えば、警告ログだけ出力してSQLログの例外は無視するとか)
        throw e;
    } finally {
        // 最後はしっかりクリアすること (必須)
        CallbackContext.clearSqlLogHandlerOnThread();
    }
}

更新系のSQLだけを記録

検索は除外して更新系のSQLだけを記録したい場合は、内部的なクラスを利用することにはなってしまいますが、BehaviorCommand クラスにて判定ができます。

ResourceContext.behaviorCommand().isSelect() が false であれば更新系となります。insert() や update() などに加え、queryUpdate() や外だしSQLの execute() も含まれます。ただし、この判定メソッドはもともとこの機能のために用意されたものではないので、業務で利用する場合はしっかりとテストを行う必要があります。

e.g. 更新系のSQLだけを記録 (Interceptor利用) @Java
public Object invoke(MethodInvocation invocation) throws Throwable {
    ... // 既に設定されていたらのチェック

    CallbackContext.setSqlLogHandlerOnThread(new SqlLogHandler() {
        public void handle(SqlLogInfo sqlLogInfo) {
            if (!ResourceContext.behaviorCommand().isSelect()) {
                // ログに出力するなり好きなように
                ...
            }
        }
    });

    try> {
        return invocation.proceed();
    } finally {
        // 最後はしっかりクリアすること (必須)
        CallbackContext.clearSqlLogHandlerOnThread();
    }
}

この ResourceContext と BehaviorCommand は、DBFluteランタイムの内部的なクラスと言えます。よって、これらクラスは DBFlute のバージョンが変わればインターフェースや挙動が変わる可能性がありますので、自動テスト(JUnitなど)としていつでも検証できる環境を整えておくことが推奨されます。