Hi all<br><br>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-<br><br><b>1. Logback is taking almost similar time as Log4j. In fact, for first few logs it is slower than Log4j.<br>
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.</b><br><br>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.<br>
<br><br><b>Code Used</b><br><br>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.<br>
<br><br>CASE I Simple Logging<br><br><font color="#3366ff">Logback Main Class<br><br></font>package com.practice.vaibhav.logback;<br><br>import org.slf4j.Logger;<br>import org.slf4j.LoggerFactory;<br><br>import ch.qos.logback.classic.LoggerContext;<br>
import ch.qos.logback.classic.joran.JoranConfigurator;<br>import ch.qos.logback.core.joran.spi.JoranException;<br><br>import com.practice.vaibhav.runner.RunnerSlf4j;<br><br>public class MainLogbackSimple {<br><br> /*<br>
* Here threshold was set to WARN. Only 1 debug message is put at the end<br> * of thread exit<br> */<br><br> final static Logger logger = LoggerFactory<br> .getLogger(MainLogbackSimple.class);<br>
<br> public static void main(String[] args) {<br><br> configureLogback();<br><br> logger.debug("Start Log");<br><br> int threadCount = 100;<br> Thread[] threads = new Thread[threadCount];<br>
<br> // Infinite Loop<br> while (true) {<br> // get start time<br> long startTime = System.nanoTime();<br><br> // Create Threads<br> for (int i = 0; i < threads.length; i++) {<br>
threads[i] = new Thread(new RunnerSlf4j(), "T " + i);<br> threads[i].start();<br> }<br><br> // Join Threads & log their IDs<br><br> for (int i = 0; i < threads.length; i++) {<br>
try {<br> threads[i].join();<br><br> logger.debug("Thread Exiting : " + threads[i].getName());<br> } catch (InterruptedException e) {<br> }<br>
}<br><br> // calculate total time<br> long endTime = System.nanoTime();<br> long timeDiff = endTime - startTime;<br><br> System.out.println("Total time taken : " + timeDiff);<br>
<br> }<br><br> }<br><br> private static void configureLogback() {<br> JoranConfigurator configurator = new JoranConfigurator();<br><br> LoggerContext lContext = (LoggerContext) LoggerFactory<br>
.getILoggerFactory();<br> configurator.setContext(lContext);<br> lContext.reset();<br> try {<br> configurator.doConfigure("logback.xml");<br> } catch (JoranException e1) {<br>
e1.printStackTrace();<br> }<br> }<br><br>}<br> <br><span style="color: rgb(51, 102, 255);">Runner Class for Threads</span><br><br>package com.practice.vaibhav.runner;<br><br>public class RunnerSlf4j implements Runnable{<br>
<br> @Override<br> public void run() {<br> <br> DateTimePrinterSlf4j printer = new DateTimePrinterSlf4j();<br><br> printer.printDebug();<br> printer.printWarn();<br> <br> //printer.printDate();<br>
}<br><br>}<br><br><br><font color="#3366ff">Printer Class<br><br></font>package com.practice.vaibhav.runner;<br>
<br>
import java.util.Date;<br>
<br>
import org.apache.log4j.Logger;<br>
<br>
public class DateTimePrinterLog4j {<br>
<br>
static final Logger logger = Logger.getLogger(DateTimePrinterLog4j.class);<br>
<br>
public void printDate() {<br>
<br>
Date todayDate = new Date();<br>
logger.debug(todayDate);<br>
}<br>
<br>
public void printDebug() {<br>
logger.debug("sample Debug Msg");<br>
}<br>
<br>
public void printWarn() {<br>
logger.warn("sample Warning Msg");<br>
}<br>
<br>
}<br><br><font color="#3366ff"><br>Property file I used<br><br style="color: rgb(0, 0, 0);"><span style="color: rgb(0, 0, 0);"><?xml version="1.0" encoding="UTF-8"?></span><br style="color: rgb(0, 0, 0);">
<span style="color: rgb(0, 0, 0);"><configuration></span><br style="color: rgb(0, 0, 0);"><span style="color: rgb(0, 0, 0);"> <appender name="FA" class="ch.qos.logback.core.FileAppender"></span><br style="color: rgb(0, 0, 0);">
<span style="color: rgb(0, 0, 0);"> <File>logs/sampleLogback1.log</File></span><br style="color: rgb(0, 0, 0);"><span style="color: rgb(0, 0, 0);"> <encoder></span><br style="color: rgb(0, 0, 0);">
<span style="color: rgb(0, 0, 0);"> <pattern>%p %t - %m%n</pattern></span><br style="color: rgb(0, 0, 0);"><span style="color: rgb(0, 0, 0);"> </encoder></span><br style="color: rgb(0, 0, 0);"><span style="color: rgb(0, 0, 0);"> <filter class="ch.qos.logback.classic.filter.ThresholdFilter"></span><br style="color: rgb(0, 0, 0);">
<span style="color: rgb(0, 0, 0);"> <level>WARN</level></span><br style="color: rgb(0, 0, 0);"><span style="color: rgb(0, 0, 0);"> </filter></span><br style="color: rgb(0, 0, 0);"><span style="color: rgb(0, 0, 0);"> </appender></span><br style="color: rgb(0, 0, 0);">
<span style="color: rgb(0, 0, 0);"> <root level="DEBUG"></span><br style="color: rgb(0, 0, 0);"><span style="color: rgb(0, 0, 0);"> <appender-ref ref="FA"/></span><br style="color: rgb(0, 0, 0);">
<span style="color: rgb(0, 0, 0);"> </root></span><br style="color: rgb(0, 0, 0);"><span style="color: rgb(0, 0, 0);"></configuration></span><br style="color: rgb(0, 0, 0);"><br><br><b>Similarly I used log4j to compare the results.</b><br>
<br>Main class for log4j<br><br></font><br>
package com.practice.vaibhav.log4j;<br>
<br>
import org.apache.log4j.Logger;<br>
import org.apache.log4j.PropertyConfigurator;<br>
<br>
import com.practice.vaibhav.runner.RunnerLog4j;<br>
<br>
public class MainLog4jSimple {<br>
<br>
static final Logger logger = Logger.getLogger(MainLog4jSimple.class);<br>
<br>
public static void main(String[] args) {<br>
<br>
configureLog4j();<br>
logger.debug("Start Log");<br>
<br>
int threadCount = 100;<br>
Thread[] threads = new Thread[threadCount];<br>
<br>
// Infinite Loop<br>
while (true) {<br>
// get start time<br>
long startTime = System.nanoTime();<br>
<br>
// Create Threads<br>
for (int i = 0; i < threads.length; i++) {<br>
threads[i] = new Thread(new RunnerLog4j(), "T " + i);<br>
threads[i].start();<br>
}<br>
<br>
// Join Threads & log their IDs<br>
<br>
for (int i = 0; i < threads.length; i++) {<br>
try {<br>
threads[i].join();<br>
<br>
logger.debug("Thread Exiting : " + threads[i].getName());<br>
} catch (InterruptedException e) {<br>
}<br>
}<br>
<br>
// calculate total time<br>
long endTime = System.nanoTime();<br>
long timeDiff = endTime - startTime;<br>
<br>
System.out.println("Total time taken : " + timeDiff);<br>
<br>
}<br>
}<br>
<br>
<br>
private static void configureLog4j() {<br>
PropertyConfigurator.configure("log4j.properties");<br>
}<br>
<br>
}<br>
<br><span style="color: rgb(51, 102, 255);">Runner Class for Threads<br><br></span>package com.practice.vaibhav.runner;<br>
<br>
public class RunnerLog4j implements Runnable{<br>
<br>
@Override<br>
public void run() {<br>
<br>
DateTimePrinterLog4j printer = new DateTimePrinterLog4j(); <br>
printer.printDebug();<br>
printer.printWarn();<br>
<br>
//printer.printDate();<br>
}<br>
<br>
}<br>
<br><font color="#3366ff">Printer class for log4j<br><br></font>package com.practice.vaibhav.runner;<br>
<br>
import java.util.Date;<br>
<br>
import org.apache.log4j.Logger;<br>
<br>
public class DateTimePrinterLog4j {<br>
<br>
static final Logger logger = Logger.getLogger(DateTimePrinterLog4j.class);<br>
<br>
public void printDate() {<br>
<br>
Date todayDate = new Date();<br>
logger.debug(todayDate);<br>
}<br>
<br>
public void printDebug() {<br>
logger.debug("sample Debug Msg");<br>
}<br>
<br>
public void printWarn() {<br>
logger.warn("sample Warning Msg");<br>
}<br>
<br>
}<br>
<br><br><font color="#3366ff">Property file used for Log4j<br><br></font>log4j.rootLogger=DEBUG, FA<br>
<br>
log4j.appender.FA=org.apache.log4j.FileAppender<br>
log4j.appender.FA.File=logs/sampleLog4j1.log<br>
log4j.appender.FA.layout=org.apache.log4j.PatternLayout<br>
log4j.appender.FA.layout.ConversionPattern=%p %t - %m%n<br>
<br>
log4j.appender.FA.Threshold = WARN<br><font color="#3366ff"><br></font><font color="#3366ff">At the end of this exercise I got following results. <br></font> <br><span style="color: rgb(51, 102, 255);">Logback</span><br>
%CPU %MEM<br>99.3 - 104.8 3.4<br><br>Total time taken : 39248000<br>Total time taken : 33907000<br>Total time taken : 37902000<br>Total time taken : 34828000<br>Total time taken : 29837000<br>Total time taken : 29597000<br>
Total time taken : 32702000<br>Total time taken : 27205000<br>Total time taken : 34473000<br>Total time taken : 27280000<br>Total time taken : 29508000<br>.<br>.<br>.<br><after stabalization><br>Total time taken : 12591000<br>
Total time taken : 11591000<br>Total time taken : 13272000<br>Total time taken : 12304000<br>Total time taken : 12932000<br>Total time taken : 11367000<br>Total time taken : 11576000<br>Total time taken : 11366000<br>Total time taken : 12620000<br>
Total time taken : 11269000<br>Total time taken : 11889000<br><br><br><br><span style="color: rgb(51, 102, 255);">Log4j</span><br>%CPU %MEM<br>99.5 - 108 5.8 - 6.6<br><br>Total time taken : 29474000<br>Total time taken : 23460000<br>
Total time taken : 22538000<br>Total time taken : 24187000<br>Total time taken : 24671000<br>Total time taken : 31946000<br>Total time taken : 21369000<br>Total time taken : 23684000<br>Total time taken : 21469000<br>Total time taken : 21057000<br>
Total time taken : 21705000<br>.<br>.<br>.<br><after stabalization><br>Total time taken : 11476000<br>Total time taken : 11175000<br>Total time taken : 11292000<br>Total time taken : 11408000<br>Total time taken : 12198000<br>
Total time taken : 10574000<br>Total time taken : 14494000<br>Total time taken : 11340000<br>Total time taken : 11409000<br>Total time taken : 12096000<br>Total time taken : 11391000<br><br><br><br><b>Here, I see no improvement in the time whatsoever. In fact, for first few cycles Logback is slower than Log4j !!</b><br>
<b>Of course, the memory usuage is lower for Logback.</b><br><br><br><b>CASE II</b> Parametrization<br><br>On the similar lines, I used parametrization to see time improvement. I changed main class like -<br><br><br> HashMap<Integer, String> map = getMap();<br>
<br> for (int i = 0; i < threads.length; i++) {<br> try {<br> threads[i].join();<br><br> logger.trace("Thread Exiting : {} {}",<br> threads[i].getName(), map);<br>
logger.debug("Thread Exiting : {} {}",<br> threads[i].getName(), map);<br> <a href="http://logger.info">logger.info</a>("Thread Exiting : {} {}", threads[i].getName(),<br>
map);<br> logger.warn("Thread Exiting : {} {}", threads[i].getName(),<br> map);<br> logger.error("Thread Exiting : {} {}",<br>
threads[i].getName(), map);<br><br> } catch (InterruptedException e) {<br> }<br><br> }<br><br>Where hashmap has 1000 elements as <br><br>for (int i = 0; i < 1000; i++) <br>
map.put(i, "Value: " + i);<br><br><br>Similarly, to check against isDebugEnabled() from Log4j I used - <br><br><br> HashMap<Integer, String> map = getMap();<br><br> for (int i = 0; i < threads.length; i++) {<br>
try {<br> threads[i].join();<br><br> if (logger.isDebugEnabled())<br> logger.trace("Thread Exiting : " + threads[i].getName()<br> + map);<br>
if (logger.isDebugEnabled())<br> logger.debug("Thread Exiting : " + threads[i].getName()<br> + map);<br> if (logger.isDebugEnabled())<br>
<a href="http://logger.info">logger.info</a>("Thread Exiting : " + threads[i].getName()<br> + map);<br> if (logger.isDebugEnabled())<br> logger.warn("Thread Exiting : " + threads[i].getName()<br>
+ map);<br> if (logger.isDebugEnabled())<br> logger.error("Thread Exiting : " + threads[i].getName()<br> + map);<br>
<br><b>I do get time improvement but it is not order of 10. Please guide me if my comparison approach is</b> <b>faulty.</b><br>Log4j gose from 2 x 10 ^ 8 to 2.3 x 10 ^ 8 nano secs. while<br>Logback takes 1.8 x 10 ^ 8 to 1.9 x 10 ^ 8 nano secs.<br>
<br><br>Since Logback relies on SLF4j, so I used SLF4j directly instead of Log4j and the results were pretty same as Logback results. <br><br><br>So, I want to know -<br><br><b>1. Where / How do I get significant improvement using Logback?<br>
2. What additional does it offer as compared to SLF4j?</b><br><br><br>If you want I can mail the entire source & results obtained as well.<br><br><br>Thanks & Regards<br>Vaibhav Malhotra<br><br><br><br>