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