[logback-user] Little /no improvement in logging time as compared to Log4j / SLF4j
Ralph Goers
rgoers at apache.org
Tue Sep 28 08:13:05 CEST 2010
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 at qos.ch
> http://qos.ch/mailman/listinfo/logback-user
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://qos.ch/pipermail/logback-user/attachments/20100927/3a6e365a/attachment-0001.html>
More information about the Logback-user
mailing list