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
_______________________________________________
user mailing list
[email protected]
http://www.slf4j.org/mailman/listinfo/user
