slf4j5 - Java logging even faster

In my previous posting where I introduced slf4j5 I reported that, to my surprise, performance was better than when using slf4j by itself - probably due to the usage of the Java 5 String formatter.

Inspired by this I took a closer look at performance and ended up creating a dedicated thread in each logger for doing the actual logging work (i/o). This resulted in more than a 50% improvement over slf4j5 without the dedicated thread. This has the added benefit of providing for non-blocking logging in a multi-threaded environment.

Get the code here: http://code.google.com/p/slf4j5/

Introducing slf4j5 - logging, varargs, String.format, faster

I was recently investigating some of the Java logging frameworks out there and really like the flexibility/abstraction layer that slf4j provides and decided to give it a try with the logback logging implementation, which is apparently the successor to log4j.

I noticed that slf4j has its own formatter built into the logging api calls for assembling parameterized strings. However, what I didn't realize is that it only accepted a maximum of 2 parameters.  Bummer.  What happened to varargs?  Turns out slf4j doesn't support Java 5 yet and it didn't sound like it was going to anytime soon.

So, I wrote a simple Java 5 wrapper around slf4j and, except for the Java 5 string formatting, you use it just like you would slf4j.  You can find it here (I'm hoping the slf4j folks will take it on as a subproject - if so, I'll update the link):

http://code.google.com/p/slf4j5/

I figured since I was adding a small layer on top of slf4j that there would be a performance penalty.  It would stand to reason, but I wanted to know how much overhead I was adding to slf4j so I wrote some tests to measure it.   I was so surprised by the results that I ran the tests over and over and reviewed the code and tweaked the tests until I convinced myself what I was seeing was actually true - the slf4j5 wrapper was actually faster than using slf4j by itself (with logback, of course).

But, how could that be? My guess is that it's primarily due to the use of String.format() rather than the custom formatter used in slf4j.

Here were the results:

In addition, I also enhanced the context-awareness to automatically log the class, method and line from which the logging call originated.

On a similar note, using this auto-detection strategy, you don't need to specify a class or a name when obtaining your logger.  For example:

LoggerFactory.getLogger() will obtain a logger for the class wherein this statement is contained.

So, varargs, advanced formatting, faster performance, auto-context detection - several good reasons to take it out for a test drive.

I will be working on the wiki, but here's an example:

public class MyClass { 

    private final Logger _log = LoggerFactory.getLogger();

    public void doSomething(int param1, String param2, double param3) { 
        _log.debug(“entering, params = %d, %s, %8.2f”, param1, param2, param3);
        
        // some useful business logic here
      
        _log.debug(“leaving”);
    } // doSomething()

    ...

The above logging statements would result in something like the following in the log file:

2012-08-22 07:33:22.543 DEBUG [main] [MyClass.doSomething():6] entering, params = 100, hello, 500.00

2012-08-22 07:33:23.618 DEBUG [main] [MyClass.doSomething():10] leaving

Let me know how it goes.