Blog

log4jdbc は logback の設定をミスってるとすげー遅い

log4jdbc を使うと jdbc でアクセスしたクエリのログが簡単にとれて便利なのだが、設定を誤るとパフォーマンスを超絶劣化させてくるので注意が必要である。 log4jdbc はデバッグレベルだと Throwable のインスタンスを取得してスタックトレースを取って、呼び出し元の情報を表示する。 これが極めて遅い。本当に驚くほど遅い。

↓具体的にはこのへんである。

  private static String getDebugInfo()
  {
    Throwable t = new Throwable();
    t.fillInStackTrace();

    StackTraceElement[] stackTrace = t.getStackTrace();

    if (stackTrace != null)

https://github.com/arthurblake/log4jdbc/blob/master/src-jdbc4/net/sf/log4jdbc/Slf4jSpyLogDelegator.java#L433-L440

このメソッドは isDebugEnabled でチェックした上で、実行されるんで、debug レベルで log4jdbc のログを出していると遅くなる。

logback ではデフォルトのログレベルが debug なので、ちゃんと <root> の設定をしていないと遅くなる。

具体的には以下のように記述すればよいだろう。デフォルトで INFO レベルのメッセージを表示して、jdbc.audit 等の無用なものは off にする。

<!-- Suppress useless log4jdbc messages -->
<logger name="jdbc.audit" additivity="false" level="off"/>
<logger name="jdbc.resultset" additivity="false" level="off"/>
<logger name="jdbc.sqlonly" additivity="false" level="off"/>

<!-- Show info level messages by default -->
<root level="info">
  <appender-ref ref="STDOUT"/>
</root>