Re: [logback-user] Little /no improvement in logging time as compared to Log4j / SLF4j

28 Sep 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@qos.ch
http://qos.ch/mailman/listinfo/logback-user

Re: [logback-user] Little /no improvement in logging time as compared to Log4j / SLF4j

Ralph Goers