[logback-user] log4j performance comparison
hostalp at post.cz
hostalp at post.cz
Fri Mar 18 19:10:51 CET 2011
Hello,
based on the old topic archived here for example: http://old.nabble.com/logback-performance-clarification-td9390741.html
I performed set of similar tests with debug level actually enabled to see how does logback perform when actually logging.
- I noticed slightly worse (than log4j) logback performance in most cases, especially on my Windows machine
- I was also interested in the effect of immediateFlush option which was giving us noticable performance improvement with log4j, but was removed from logback as of 0.9.19 (http://logback.qos.ch/manual/appenders.html).
Here I noticed that immediateFlush was still giving something (I had to test on logback 0.9.18 in order to compare that). Sad that it was removed.
- I've also done some more tests with info level and logback parametrized debug call combined with isDebugEnabled and this one shows typically better performance than plain parametrized debug call as well as classic debug call with isDebugLevel.
The main question is - why was immediateFlush removed when it really gives some improvement?
Here are some results (all tests performed on Java 1.5 due to its use by the application server we're running at):
Windows: log4j 1.2.16, logback 0.9.28 immediateFlush true:
###############################################
Log4j direct debug call: 13516
Log4j tested (isDebugEnabled) debug call: 13595
Logback direct debug call: 15593
Logback tested (isDebugEnabled) debug call: 17273
Logback parametrized debug call: 19011
###############################################
Windows: log4j 1.2.16, logback 0.9.18 immediateFlush true:
###############################################
Log4j direct debug call: 13421
Log4j tested (isDebugEnabled) debug call: 13240
Logback direct debug call: 15562
Logback tested (isDebugEnabled) debug call: 17112
Logback parametrized debug call: 17981
###############################################
Windows: log4j 1.2.16, logback 0.9.18 immediateFlush false:
###############################################
Log4j direct debug call: 6562
Log4j tested (isDebugEnabled) debug call: 6608
Logback direct debug call: 6137
Logback tested (isDebugEnabled) debug call: 7418
Logback parametrized debug call: 8273
###############################################
HP-UX: log4j 1.2.16, logback 0.9.28 immediateFlush true:
###############################################
Log4j direct debug call: 17385
Log4j tested (isDebugEnabled) debug call: 17411
Logback direct debug call: 17351
Logback tested (isDebugEnabled) debug call: 17315
Logback parametrized debug call: 17677
###############################################
HP-UX: log4j 1.2.16, logback 0.9.18 immediateFlush true:
###############################################
Log4j direct debug call: 17522
Log4j tested (isDebugEnabled) debug call: 17688
Logback direct debug call: 17418
Logback tested (isDebugEnabled) debug call: 17525
Logback parametrized debug call: 17071
###############################################
HP-UX machine: log4j 1.2.16, logback 0.9.18 immediateFlush false:
###############################################
Log4j direct debug call: 9936
Log4j tested (isDebugEnabled) debug call: 10869
Logback direct debug call: 9900
Logback tested (isDebugEnabled) debug call: 9907
Logback parametrized debug call: 10346
###############################################
code used for testing
----------------------------------------------------------------------------------------------
package perfTest.ch.qos.logback;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class PerformanceComparator {
static Logger logbacklogger = LoggerFactory.getLogger(PerformanceComparator.class);
static org.apache.log4j.Logger log4jlogger = org.apache.log4j.Logger.getLogger(PerformanceComparator.class);
// How many times should we try to log:
static int loop = 1000000;
public static void main(String[] args) throws InterruptedException {
initConfig();
// Let's run once for Just In Time compiler
log4jDirectDebugCall();
log4jTestedDebugCall();
logbackDirectDebugCall();
logbackTestedDebugCall();
logbackParametrizedDebugCall();
// let's run the tests and display the results:
long result1 = log4jDirectDebugCall();
long result2 = log4jTestedDebugCall();
long result3 = logbackDirectDebugCall();
long result4 = logbackTestedDebugCall();
long result5 = logbackParametrizedDebugCall();
System.out.println("###############################################");
System.out.println("Log4j direct debug call: " + result1);
System.out.println("Log4j tested (isDebugEnabled) debug call: " + result2);
System.out.println("Logback direct debug call: " + result3);
System.out.println("Logback tested (isDebugEnabled) debug call: " + result4);
System.out.println("Logback parametrized debug call: " + result5);
System.out.println("###############################################");
}
private static long log4jDirectDebugCall() {
Integer j = new Integer(2);
long start = System.nanoTime();
for (int i = 0; i < loop; i++) {
log4jlogger.debug("SEE IF THIS IS LOGGED " + j + ".");
}
return (System.nanoTime() - start) / loop;
}
private static long log4jTestedDebugCall() {
Integer j = new Integer(2);
long start = System.nanoTime();
for (int i = 0; i < loop; i++) {
if (log4jlogger.isDebugEnabled()) {
log4jlogger.debug("SEE IF THIS IS LOGGED " + j + ".");
}
}
return (System.nanoTime() - start) / loop;
}
private static long logbackDirectDebugCall() {
Integer j = new Integer(2);
long start = System.nanoTime();
for (int i = 0; i < loop; i++) {
logbacklogger.debug("SEE IF THIS IS LOGGED " + j + ".");
}
return (System.nanoTime() - start) / loop;
}
private static long logbackTestedDebugCall() {
Integer j = new Integer(2);
long start = System.nanoTime();
for (int i = 0; i < loop; i++) {
if (logbacklogger.isDebugEnabled())
logbacklogger.debug("SEE IF THIS IS LOGGED " + j + ".");
}
return (System.nanoTime() - start) / loop;
}
private static long logbackParametrizedDebugCall() {
Integer j = new Integer(2);
long start = System.nanoTime();
for (int i = 0; i < loop; i++) {
//if (logbacklogger.isDebugEnabled()) //test
logbacklogger.debug("SEE IF THIS IS LOGGED {}.", j);
}
return (System.nanoTime() - start) / loop;
}
private static void initConfig() {
org.apache.log4j.Logger log4jRoot = org.apache.log4j.Logger.getRootLogger();
//log4jRoot.setLevel(org.apache.log4j.Level.INFO);
ch.qos.logback.classic.Logger lbRoot = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger("ROOT");
//lbRoot.setLevel(ch.qos.logback.classic.Level.INFO);
// create the loggers
org.apache.log4j.Logger.getLogger("perfTest");
org.apache.log4j.Logger.getLogger("perfTest.ch");
org.apache.log4j.Logger.getLogger("perfTest.ch.qos");
org.apache.log4j.Logger.getLogger("perfTest.ch.qos.logback");
LoggerFactory.getLogger("perfTest");
LoggerFactory.getLogger("perfTest.ch");
LoggerFactory.getLogger("perfTest.ch.qos");
LoggerFactory.getLogger("perfTest.ch.qos.logback");
}
}
----------------------------------------------------------------------------------------------
log4j configuration
----------------------------------------------------------------------------------------------
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false">
<appender name="TestLogfile" class="org.apache.log4j.RollingFileAppender">
<param name="File" value="testlog4j.log"/>
<param name="MaxFileSize" value="1000KB"/>
<param name="maxBackupIndex" value="1"/>
<param name="immediateFlush" value="true"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ISO8601} %5p [%t] %c{1} %X{transactionId} - %m%n"/>
</layout>
</appender>
<root>
<level value="debug"/>
<appender-ref ref="TestLogfile"/>
</root>
</log4j:configuration>
----------------------------------------------------------------------------------------------
logback 0.9.28 configuration
----------------------------------------------------------------------------------------------
<configuration>
<appender name="TestLogfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>testlogback.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
<fileNamePattern>testlogback.log.%i</fileNamePattern>
<minIndex>1</minIndex>
<maxIndex>1</maxIndex>
</rollingPolicy>
<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
<maxFileSize>1000KB</maxFileSize>
</triggeringPolicy>
<encoder>
<Pattern>%d{ISO8601} %5p [%t] %c{0} %X{transactionId} - %m%n</Pattern>
<charset>UTF-8</charset>
</encoder>
</appender>
<root>
<level value="debug" />
<appender-ref ref="TestLogfile" />
</root>
</configuration>
----------------------------------------------------------------------------------------------
logback 0.9.18 configuration
----------------------------------------------------------------------------------------------
<configuration>
<appender name="TestLogfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
<File>testlogback.log</File>
<ImmediateFlush>true</ImmediateFlush>
<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
<FileNamePattern>testlogback.log.%i</FileNamePattern>
<MinIndex>1</MinIndex>
<MaxIndex>1</MaxIndex>
</rollingPolicy>
<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
<MaxFileSize>1000KB</MaxFileSize>
</triggeringPolicy>
<Encoding>UTF-8</Encoding>
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>%d{ISO8601} %5p [%t] %c{0} %X{transactionId} - %m%n</Pattern>
</layout>
</appender>
<root>
<level value="debug" />
<appender-ref ref="TestLogfile" />
</root>
</configuration>
----------------------------------------------------------------------------------------------
More information about the Logback-user
mailing list