デバッグログ
デバッグログとは？
主に開発中に、ディベロッパーがデバッグ用に実行された処理の詳細情報を得るためのログです。
DBFluteでは、主に sQLの実行ログ(sQL自体も含む) を示します。
デバッグログの設定
DBFluteでは、Commons Logging を利用し、DEBUGレベルでログを出力しています。
ここでは、Commons Logging 対応ライブラリである Log4j を前提に説明をします。その他、説明上の前提がありますが、実際に利用するときにこの通りである必要はありません。
- Commons Logging の実行ライブラリとして Log4j を利用
- "log4j.properties" を利用(XMLではない)
- "console" という名前の Appender が設定されている
DBFluteパッケージをログ出力の対象に
DBFluteパッケージをログ出力の対象にすることで、sQL実行ログが出力されます。
e.g. DBFluteパッケージをログ出力の対象にする @log4j.properties
log4j.logger.org.seasar.dbflute = ALL, console
例えば、DIコンテナに seasar を利用していて org.seasar が既にログ出力の対象になっている場合は、DBFluteパッケージを明示的に設定する必要はありません。 (明示的に OFF にしない限り、親パッケージの設定が継承されるはずです)
ログレイアウトを調整
ログレイアウトをしっかり調整することで、デバッグログがさらに見やすいものになります。 例えば、ログ出力したクラスやメソッド名にソースファイル上の行番号などを表示することで、 そのログメッセージの意味がわかりやすいものとなると同時に、トレースする際にその情報が多いに役に立ちます。
e.g. foo アペンダのログレイアウトをいい感じに @log4j.properties
log4j.appender.foo=org.apache.log4j.ConsoleAppender
...
log4j.appender.foo.layout=org.apache.log4j.PatternLayout
log4j.appender.foo.layout.ConversionPattern=%d [%t]-%-5p (%C{1}#%M():%L) - %m%n
ツールなどで Log4j の設定ファイルも自動生成されるような場合、簡易なレイアウトになっていることもありますので、 内容を確認してしっかり設定をすることが推奨されます。
e.g. ログレイアウトをいい感じにした場合のログ @log4j.properties
...:29:16,989 [main]-INFO (DBFluteInitializer#announce():56) - ...Initializing DBFlute components
...:29:16,996 [main]-INFO (DBFluteConfig#unlock():568) - ...Unlocking the configuration of DBFlute
...:29:16,997 [main]-INFO (DBFluteConfig#setDatasourceHandler():287) - ...setting datasourceHandler: springDBCPDatasourceHandler(for spring and Commons-DBCP)
...:29:16,997 [main]-INFO (DBFluteConfig#lock():558) - ...Locking the configuration of DBFlute
...:29:18,077 [main]-DEBUG (XLog#log():41) - ...Initializing sqlExecution for the key 'MEMBER:selectList(MemberCB):Member'
...:29:18,259 [main]-DEBUG (XLog#log():41) - sqlExecution Initialization Cost: [00m00s183ms]
...
DBFluteのsQL実行ログ
主な要素は以下の通りです。
- Behaviorの呼び出しメソッド
- どの Behavior の、どのメソッドが呼び出されたかがタイトル風に出力されます。
- Behaviorを呼び出したクラスの情報
- どのクラスのどのメソッドの何行目で Behavior のメソッドを呼び出したかが出力されます。 Pageクラス、Actionクラス、serviceクラス、Facadeクラス、Logicクラスから呼び出された場合に情報が出力されます。
- 実行されるsQLの表示用sQL
- 実行されるsQLの表示用sQL(Displaysql)が出力されます。(sQLが実行される直前に)
- 実行されたsQLの結果概要
- 呼び出された Behavior のメソッドが処理コスト(実質的にsQLの処理コストの近似値となる)、 (検索などの)結果件数、結果データの一部情報(リスト検索の場合は一件目のみ)が出力されます。
e.g. DBFluteのsQLの実行ログ(ConditionBean) {MEMBER} @Console
- /===========================================================================
- MemberBhv.selectList()
- =====================/
- MemberAdminPage.initialize():43 --> ...
- select dfloc.MEMBER_ID as MEMBER_ID, dfloc.MEMBER_NAME as MEMBER_NAME, dfloc.MEMBER_ACCOUNT as MEMBER_ACCOUNT, dfloc.MEMBER_sTATUs_CODE as MEMBER_sTATUs_CODE, dfloc.FORMALIZED_DATETIME as FORMALIZED_DATETIME, dfloc.BIRTHDATE as BIRTHDATE, dfloc.REGIsTER_DATETIME as REGIsTER_DATETIME, dfloc.REGIsTER_UsER as REGIsTER_UsER, dfloc.REGIsTER_PROCEss as REGIsTER_PROCEss, dfloc.UPDATE_DATETIME as UPDATE_DATETIME, dfloc.UPDATE_UsER as UPDATE_UsER, dfloc.UPDATE_PROCEss as UPDATE_PROCEss, dfloc.VERsION_NO as VERsION_NO, dfrel_0.MEMBER_sTATUs_CODE as MEMBER_sTATUs_CODE_0, dfrel_0.MEMBER_sTATUs_NAME as MEMBER_sTATUs_NAME_0, dfrel_0.DIsPLAY_ORDER as DIsPLAY_ORDER_0
- from MEMBER dfloc
- left outer join MEMBER_sTATUs dfrel_0 on dfloc.MEMBER_sTATUs_CODE = dfrel_0.MEMBER_sTATUs_CODE
- where dfloc.MEMBER_NAME like 's%' escape '|'
- order by dfloc.MEMBER_ID asc
- ===========/ [00m00s016ms (4) first={1,stojkovic,Pixy,FML,2007-12-01 02:01:10.0,1965-03-02 15:00:00.0,2008-01-23 13:38:25.989,replace-schema,replace-schema,2008-01-23 13:38:25.991,replace-schema,replace-schema,1}]
この要素の中の、"実行されるsQLの表示用sQL" を QueryLog、それ以外の要素をまとめて ExecutestatusLog と呼びます。
これらログを DEBUG ではなく、オプションで INFO レベルで出力するように変更することも可能です。また、QueryLog は QLog というクラス、ExecutestatusLog は XLog というクラスから出力されますので、Log4j の設定でそれらクラスを利用して制御できます。
DBFluteの様々なログ
TODO jflute now writing
Exampleのススメ
dbflute-basic-example では、実際にデバッグログの設定がされていて、テストケース実行時にそのログをコンソールで確認することができます。 (他のほとんどのExampleでも同様に設定されています)
