log4jdbcを使ったSQL(JDBC)のトレース

こんにちは、開発本部の榎本です。

開発中にデータベースに対してどのようなクエリが流れているのか確認してみたいことありませんか?

以前、山寺さんが紹介していたResinのログで取得するなど、いろいろな方法があるのですが、今回は、log4jdbc(http://code.google.com/p/log4jdbc/)を利用したトレース方法を紹介します。
今回は例としてWebPlatform上での設定を紹介します。

設定手順

http://code.google.com/p/log4jdbc/downloads/listよりlog4jdbc4-*.jarをダウンロードします。
%WebPlatform%/lib配下にダウンロードしたjarファイルを配置します。
%WebPlatform%/conf/http.xmlを編集します。

これまでデータベース(データソース)の設定項目に、データベース固有のJDBCドライバが設定されますが(type)その部分を"net.sf.log4jdbc.DriverSpy"に差し替えます。
また、urlに含まれるjdbc:...の部分をjdbc:log4jdbc:...に変更します。

変更前:

<database>
  <jndi-name>jdbc/default</jndi-name>
  <driver>
   <type>org.postgresql.Driver</type>
   <url>jdbc:postgresql://127.0.0.1:5432/iwp723</url>
    <user>USER</user>
    <password>PASSWORD</password>
  </driver>
  <prepared-statement-cache-size>8</prepared-statement-cache-size>
  <max-connections>20</max-connections>
  <max-idle-time>30s</max-idle-time>
</database>

<jndi-name>jdbc/default</jndi-name>

<type>org.postgresql.Driver</type>

<url>jdbc:postgresql://127.0.0.1:5432/iwp723</url>

<password>PASSWORD</password>

</driver>

<prepared-statement-cache-size>8</prepared-statement-cache-size>

<max-connections>20</max-connections>

<max-idle-time>30s</max-idle-time>

</database>

変更後:

<database>
  <jndi-name>jdbc/default</jndi-name>
  <driver>
   <type>net.sf.log4jdbc.DriverSpy</type>
   <url>jdbc:log4jdbc:postgresql://127.0.0.1:5432/iwp723</url>
    <user>USER</user>
    <password>PASSWORD</password>
  </driver>
  <prepared-statement-cache-size>8</prepared-statement-cache-size>
  <max-connections>20</max-connections>
  <max-idle-time>30s</max-idle-time>
</database>

<jndi-name>jdbc/default</jndi-name>

<type>net.sf.log4jdbc.DriverSpy</type>

<url>jdbc:log4jdbc:postgresql://127.0.0.1:5432/iwp723</url>

<password>PASSWORD</password>

</driver>

<prepared-statement-cache-size>8</prepared-statement-cache-size>

<max-connections>20</max-connections>

<max-idle-time>30s</max-idle-time>

</database>

typeの部分を変更しています。
それ以外の項目は環境に合わせて設定してください。

%WebPlatform%/conf/log配下にim_logger_log4jdbc.xmlファイルを作成し、以下の内容を設定します。

<included>
  <logger name="jdbc.sqlonly" additivity="false">
    <level value="off" />
    <appender-ref ref="STDOUT" />
  </logger>
  <logger name="jdbc.sqltiming" additivity="false">
    <level value="info" />
    <appender-ref ref="STDOUT" />
  </logger>
  <logger name="jdbc.audit" additivity="false">
    <level value="off" />
    <appender-ref ref="STDOUT" />
  </logger>
  <logger name="jdbc.resultset" additivity="false">
    <level value="off" />
    <appender-ref ref="STDOUT" />
  </logger>
  <logger name="jdbc.connection" additivity="false">
    <level value="info" />
    <appender-ref ref="STDOUT" />
  </logger>
</included>

<appender-ref ref="STDOUT" />

</logger>

<appender-ref ref="STDOUT" />

</logger>

<appender-ref ref="STDOUT" />

</logger>

<appender-ref ref="STDOUT" />

</logger>

<appender-ref ref="STDOUT" />

</logger>

</included>

の部分をに変更することによりログの制御を切り替えることが出来ます。

WebPlatformを起動してください、SQL(JDBC)に関するログがコンソールに出力されるようになったはずです。

[INFO] j.sqltiming - select mp.menu_id as menu_id from b_m_menu_public_group_b mp, b_m_public_group_attach_t pa
where pa.user_cd = 'aoyagi' and pa.start_date  '2011/08/26|16:54:58'
and mp.public_group_set_cd = pa.public_group_set_cd and mp.public_group_cd = pa.public_group_cd
 {executed in 5 msec}
[INFO] j.sqltiming - select parent_menu_id,menu_id from b_m_menu_b  {executed in 6 msec}
[INFO] j.sqltiming - select menu_id,locale_id,display_name from b_m_menu_i  {executed in 10 msec}
[INFO] j.sqltiming - select menu_id,argument_name,argument_value from b_m_menu_argument_b  {executed in 23 msec}

[INFO] j.sqltiming - select mp.menu_id as menu_id from b_m_menu_public_group_b mp, b_m_public_group_attach_t pa

where pa.user_cd = 'aoyagi' and pa.start_date '2011/08/26|16:54:58'

and mp.public_group_set_cd = pa.public_group_set_cd and mp.public_group_cd = pa.public_group_cd

{executed in 5 msec}

[INFO] j.sqltiming - select parent_menu_id,menu_id from b_m_menu_b {executed in 6 msec}

[INFO] j.sqltiming - select menu_id,locale_id,display_name from b_m_menu_i {executed in 10 msec}

[INFO] j.sqltiming - select menu_id,argument_name,argument_value from b_m_menu_argument_b {executed in 23 msec}

クエリの内容と実行時間が確認できたかと思います。

im_logger_log4jdbc.xmlの設定を変更することにより、ResultSetやConnectionに対する操作ログ等も確認が可能となります。
開発時や障害解析の時などに使えると思いますので、機会があれば試してみてください。