デバッグログ
デバッグログとは？
主に開発中に、ディベロッパーがデバッグ用に実行された処理の詳細情報を得るためのログです。
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でも同様に設定されています)
