[logback-user] Little /no improvement in logging time as compared to Log4j / SLF4j
Vaibhav Malhotra
vaibhavm.842 at gmail.com
Mon Sep 27 16:10:31 CEST 2010
Hi all
I have been playing with Logback for past few days. My area of concern is
performance as compared to its ancestor Log4j. so far what I could find is
something like-
*1. Logback is taking almost similar time as Log4j. In fact, for first few
logs it is slower than Log4j.
2. It sure has some advantage when coming to parametrized logging as
compared to isDebugEnabled() but one can also use slf4j directly and get the
same speed.*
I am mailing code fragment & results obtained. Please correct me if my
approach is inappropriate. Also tell me the "critical cases" where Logback
outperforms Log4j.
*Code Used*
Here I configure the logger in the main class & create 100 threads. These
threads create a printer object in their run methods. The printer class logs
simple debug messages. The main thread joins each thread & logs their IDs. I
print total time taken for logging only at the end of each such cycle. <I
consider one cycle from child threads creation till their exits> These
cycles continue infinitely.
CASE I Simple Logging
Logback Main Class
package com.practice.vaibhav.logback;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.joran.JoranConfigurator;
import ch.qos.logback.core.joran.spi.JoranException;
import com.practice.vaibhav.runner.RunnerSlf4j;
public class MainLogbackSimple {
/*
* Here threshold was set to WARN. Only 1 debug message is put at the
end
* of thread exit
*/
final static Logger logger = LoggerFactory
.getLogger(MainLogbackSimple.class);
public static void main(String[] args) {
configureLogback();
logger.debug("Start Log");
int threadCount = 100;
Thread[] threads = new Thread[threadCount];
// Infinite Loop
while (true) {
// get start time
long startTime = System.nanoTime();
// Create Threads
for (int i = 0; i < threads.length; i++) {
threads[i] = new Thread(new RunnerSlf4j(), "T " + i);
threads[i].start();
}
// Join Threads & log their IDs
for (int i = 0; i < threads.length; i++) {
try {
threads[i].join();
logger.debug("Thread Exiting : " +
threads[i].getName());
} catch (InterruptedException e) {
}
}
// calculate total time
long endTime = System.nanoTime();
long timeDiff = endTime - startTime;
System.out.println("Total time taken : " + timeDiff);
}
}
private static void configureLogback() {
JoranConfigurator configurator = new JoranConfigurator();
LoggerContext lContext = (LoggerContext) LoggerFactory
.getILoggerFactory();
configurator.setContext(lContext);
lContext.reset();
try {
configurator.doConfigure("logback.xml");
} catch (JoranException e1) {
e1.printStackTrace();
}
}
}
Runner Class for Threads
package com.practice.vaibhav.runner;
public class RunnerSlf4j implements Runnable{
@Override
public void run() {
DateTimePrinterSlf4j printer = new DateTimePrinterSlf4j();
printer.printDebug();
printer.printWarn();
//printer.printDate();
}
}
Printer Class
package com.practice.vaibhav.runner;
import java.util.Date;
import org.apache.log4j.Logger;
public class DateTimePrinterLog4j {
static final Logger logger =
Logger.getLogger(DateTimePrinterLog4j.class);
public void printDate() {
Date todayDate = new Date();
logger.debug(todayDate);
}
public void printDebug() {
logger.debug("sample Debug Msg");
}
public void printWarn() {
logger.warn("sample Warning Msg");
}
}
Property file I used
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="FA" class="ch.qos.logback.core.FileAppender">
<File>logs/sampleLogback1.log</File>
<encoder>
<pattern>%p %t - %m%n</pattern>
</encoder>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>WARN</level>
</filter>
</appender>
<root level="DEBUG">
<appender-ref ref="FA"/>
</root>
</configuration>
*Similarly I used log4j to compare the results.*
Main class for log4j
package com.practice.vaibhav.log4j;
import org.apache.log4j.Logger;
import org.apache.log4j.PropertyConfigurator;
import com.practice.vaibhav.runner.RunnerLog4j;
public class MainLog4jSimple {
static final Logger logger = Logger.getLogger(MainLog4jSimple.class);
public static void main(String[] args) {
configureLog4j();
logger.debug("Start Log");
int threadCount = 100;
Thread[] threads = new Thread[threadCount];
// Infinite Loop
while (true) {
// get start time
long startTime = System.nanoTime();
// Create Threads
for (int i = 0; i < threads.length; i++) {
threads[i] = new Thread(new RunnerLog4j(), "T " + i);
threads[i].start();
}
// Join Threads & log their IDs
for (int i = 0; i < threads.length; i++) {
try {
threads[i].join();
logger.debug("Thread Exiting : " +
threads[i].getName());
} catch (InterruptedException e) {
}
}
// calculate total time
long endTime = System.nanoTime();
long timeDiff = endTime - startTime;
System.out.println("Total time taken : " + timeDiff);
}
}
private static void configureLog4j() {
PropertyConfigurator.configure("log4j.properties");
}
}
Runner Class for Threads
package com.practice.vaibhav.runner;
public class RunnerLog4j implements Runnable{
@Override
public void run() {
DateTimePrinterLog4j printer = new DateTimePrinterLog4j();
printer.printDebug();
printer.printWarn();
//printer.printDate();
}
}
Printer class for log4j
package com.practice.vaibhav.runner;
import java.util.Date;
import org.apache.log4j.Logger;
public class DateTimePrinterLog4j {
static final Logger logger =
Logger.getLogger(DateTimePrinterLog4j.class);
public void printDate() {
Date todayDate = new Date();
logger.debug(todayDate);
}
public void printDebug() {
logger.debug("sample Debug Msg");
}
public void printWarn() {
logger.warn("sample Warning Msg");
}
}
Property file used for Log4j
log4j.rootLogger=DEBUG, FA
log4j.appender.FA=org.apache.log4j.FileAppender
log4j.appender.FA.File=logs/sampleLog4j1.log
log4j.appender.FA.layout=org.apache.log4j.PatternLayout
log4j.appender.FA.layout.ConversionPattern=%p %t - %m%n
log4j.appender.FA.Threshold = WARN
At the end of this exercise I got following results.
Logback
%CPU %MEM
99.3 - 104.8 3.4
Total time taken : 39248000
Total time taken : 33907000
Total time taken : 37902000
Total time taken : 34828000
Total time taken : 29837000
Total time taken : 29597000
Total time taken : 32702000
Total time taken : 27205000
Total time taken : 34473000
Total time taken : 27280000
Total time taken : 29508000
.
.
.
<after stabalization>
Total time taken : 12591000
Total time taken : 11591000
Total time taken : 13272000
Total time taken : 12304000
Total time taken : 12932000
Total time taken : 11367000
Total time taken : 11576000
Total time taken : 11366000
Total time taken : 12620000
Total time taken : 11269000
Total time taken : 11889000
Log4j
%CPU %MEM
99.5 - 108 5.8 - 6.6
Total time taken : 29474000
Total time taken : 23460000
Total time taken : 22538000
Total time taken : 24187000
Total time taken : 24671000
Total time taken : 31946000
Total time taken : 21369000
Total time taken : 23684000
Total time taken : 21469000
Total time taken : 21057000
Total time taken : 21705000
.
.
.
<after stabalization>
Total time taken : 11476000
Total time taken : 11175000
Total time taken : 11292000
Total time taken : 11408000
Total time taken : 12198000
Total time taken : 10574000
Total time taken : 14494000
Total time taken : 11340000
Total time taken : 11409000
Total time taken : 12096000
Total time taken : 11391000
*Here, I see no improvement in the time whatsoever. In fact, for first few
cycles Logback is slower than Log4j !!*
*Of course, the memory usuage is lower for Logback.*
*CASE II* Parametrization
On the similar lines, I used parametrization to see time improvement. I
changed main class like -
HashMap<Integer, String> map = getMap();
for (int i = 0; i < threads.length; i++) {
try {
threads[i].join();
logger.trace("Thread Exiting : {} {}",
threads[i].getName(), map);
logger.debug("Thread Exiting : {} {}",
threads[i].getName(), map);
logger.info("Thread Exiting : {} {}",
threads[i].getName(),
map);
logger.warn("Thread Exiting : {} {}",
threads[i].getName(),
map);
logger.error("Thread Exiting : {} {}",
threads[i].getName(), map);
} catch (InterruptedException e) {
}
}
Where hashmap has 1000 elements as
for (int i = 0; i < 1000; i++)
map.put(i, "Value: " + i);
Similarly, to check against isDebugEnabled() from Log4j I used -
HashMap<Integer, String> map = getMap();
for (int i = 0; i < threads.length; i++) {
try {
threads[i].join();
if (logger.isDebugEnabled())
logger.trace("Thread Exiting : " +
threads[i].getName()
+ map);
if (logger.isDebugEnabled())
logger.debug("Thread Exiting : " +
threads[i].getName()
+ map);
if (logger.isDebugEnabled())
logger.info("Thread Exiting : " +
threads[i].getName()
+ map);
if (logger.isDebugEnabled())
logger.warn("Thread Exiting : " +
threads[i].getName()
+ map);
if (logger.isDebugEnabled())
logger.error("Thread Exiting : " +
threads[i].getName()
+ map);
*I do get time improvement but it is not order of 10. Please guide me if my
comparison approach is* *faulty.*
Log4j gose from 2 x 10 ^ 8 to 2.3 x 10 ^ 8 nano secs. while
Logback takes 1.8 x 10 ^ 8 to 1.9 x 10 ^ 8 nano secs.
Since Logback relies on SLF4j, so I used SLF4j directly instead of Log4j and
the results were pretty same as Logback results.
So, I want to know -
*1. Where / How do I get significant improvement using Logback?
2. What additional does it offer as compared to SLF4j?*
If you want I can mail the entire source & results obtained as well.
Thanks & Regards
Vaibhav Malhotra
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://qos.ch/pipermail/logback-user/attachments/20100927/452cde8d/attachment-0001.html>
More information about the Logback-user
mailing list