[slf4j-user] Performance and the JDK1.4 logger

[Ian Carr]

I am doing some performance analysis on an application we have developed and have come across an issue with Hibernate, Slf4j and The JDK1.4 logger.

It would appear that Hibernate has a number of debug and trace log events with single String arguments. These are targeted at the commons logging framework.

I am running the Application in Tomcat using the SLF4j JCL replacement library and JDK1.4 implementation layer (all at version 1.4.3).

I have noticed significant delays in processing in certain areas and running the application under a profiler the hotspot is Throwable.getStackTrace, called from (disabled) debug and trace logging statements.

It would appear from browsing the SLF4J source that the trace(String) and debug(String) (and some others) implementations for JDK1.4 logging (org.slf4j.impl. JDK14LoggerAdapter) do not have 'level enabled' gating and fall straight through to the private log method eg:

  /**
   * Log a message object at level FINE.
   *
   * @param msg -
   *          the message object to be logged
   */
  public void debug(String msg) {
    log(SELF, Level.FINE, msg, null);
  }

Rather than the gated methods like:

/**
   * Log a message at level FINEST according to the specified format and argument.
   *
   * <p>
   * This form avoids superfluous object creation when the logger is disabled
   * for level FINEST.
   * </p>
   *
   * @param format
   *          the format string
   * @param arg
   *          the argument
   */
  public void trace(String format, Object arg) {
    if (logger.isLoggable(Level.FINEST)) {
      String msgStr = MessageFormatter.format(format, arg);
      log(SELF, Level.FINEST, msgStr, null);
    }
  }

This private log() method then calls through to the fillCallerData method which calls the (slow) method getStackTrace on Throwable, irrespective of whether the appropriate log level is enabled or not.

  /**
   * Log the message at the specified level with the specified
   * throwable if any. This method creates a LogRecord and fills
   * in caller date before calling this instance's JDK14 logger.
   *
   * See bug report #13 for more details.
   * @param level
   * @param msg
   * @param t
   */
  private void log(String callerFQCN, Level level, String msg, Throwable t) {
    // millis and thread are filled by the constructor
    LogRecord record = new LogRecord(level, msg);
    record.setLoggerName(getName());
    record.setThrown(t);
    fillCallerData(callerFQCN, record);
    logger.log(record);

  }

  static String SELF = JDK14LoggerAdapter.class.getName();
  static String SUPER = MarkerIgnoringBase.class.getName();
  /**
   * Fill in caller data if possible.
   *
   * @param record The record to update
   */
  final private void fillCallerData(String callerFQCN, LogRecord record) {
    StackTraceElement[] steArray = new Throwable().getStackTrace();


I believe the either the trace, debug etc methods or the private log method should be gated with:

   if (logger.isLoggable(...){
        ...
   }

Appologies in advance if I have the wrong end of the stick!

Ian