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. Ralph On Sep 27, 2010, at 7:10 AM, Vaibhav Malhotra wrote:

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

_______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user