<html><head></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space; ">Logging framework performance is typically measured by the cost of logging when logging is completely disabled. In most systems the vast majority of log events are filtered so a system that efficiently filters them is desirable. In addition, once an event passes the filters it will need to be written to one or more locations. These will involve sockets, file i/o etc which is significantly slower than all the other work the logging framework performs. In the parameterization case the benefit is that no string operations are performed until the event has passed filtering. Since you wrapped your log4j calls in isDebugEnabled calls you should not expect to see a significant performance difference even if debug isn't enabled. The benefit comes in where isDebugEnabled is omitted and that SLF4J doesn't require the call making the code cleaner.<div><br></div><div>Ralph</div><div><br><div><div>On Sep 27, 2010, at 7:10 AM, Vaibhav Malhotra wrote:</div><br class="Apple-interchange-newline"><blockquote type="cite">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>
_______________________________________________<br>Logback-user mailing list<br><a href="mailto:Logback-user@qos.ch">Logback-user@qos.ch</a><br>http://qos.ch/mailman/listinfo/logback-user<br></blockquote></div><br></div></body></html>