For the first time in my life I find myself in a position where I’m writing a Java API that will be open sourced. Hopefully to be included in many other projects.

For logging I (and indeed the people I work with) have always used JUL (java.util.logging) and never had any issues with it. However now I need to understand in more detail what I should do for my API development. I’ve done some research on this and with the information I’ve got I just get more confused. Hence this post.

Since I come from JUL I’m biased on that. My knowledge of the rest is not that big.

From the research I’ve done I’ve come up with these reasons why people do not like JUL:

1. “I started developing in Java long before Sun released JUL and it was just easier for me to continue with logging-framework-X rather than to learn something new”. Hmm. I’m not kidding, this is actually what people say. With this argument we could all be doing COBOL. (however I can certainly relate to this being a lazy dude myself)

2. “I don’t like the names of the logging levels in JUL”. Ok, seriously, this is just not enough of a reason to introduce a new dependency.

3. “I don’t like the standard format of the output from JUL”. Hmm. This is just configuration. You do not even have to do anything code-wise. (true, back in old days you may have had to create your own Formatter class to get it right).

4. “I use other libraries that also use logging-framework-X so I thought it easier just to use that one”. This is a circular argument, isn’t ? Why does ‘everybody’ use logging-framework-X and not JUL?

5. “Everybody else is using logging-framework-X”. This to me is just a special case of the above. Majority is not always right.

So the real big question is why not JUL?. What is it I have missed ? The raison d’être for logging facades (SLF4J, JCL) is that multiple logging implementations have existed historically and the reason for that really goes back to the era before JUL as I see it. If JUL was perfect then logging facades wouldn’t exist, or what? To make matters more confusing JUL is to some extent a facade itself, allowing Handlers, Formatters and even the LogManager to be swapped.

Rather than embracing multiple ways of doing the same thing (logging), shouldn’t we question why they were necessary in the first place? (and see if those reasons still exist)

Ok, my research so far has led to a couple of things that I can see may be real issues with JUL:

1. Performance. Some say that performance in SLF4J is superior to the rest. This seems to me to be a case of premature optimization. If you need to log hundreds of megabytes per second then I’m not sure you are on the right path anyway. JUL has also evolved and the tests you did on Java 1.4 may no longer be true. You can read about it here and this fix has made it into Java 7. Many also talk about the overhead of string concatenation in logging methods. However template based logging avoids this cost and it exist also in JUL. Personally I never really write template based logging. Too lazy for that. For example if I do this with JUL:

    log.finest("Lookup request from username=" + username 
       + ", valueX=" + valueX
       + ", valueY=" + valueY));
   

   my IDE will warn me and ask permission that it should change it to:

    log.log(Level.FINEST, "Lookup request from username={0}, valueX={1}, valueY={2}", 
       new Object[]{username, valueX, valueY});
   

   .. which I will of course accept. Permission granted ! Thank you for your help.

   So I don’t actually write such statements myself, that is done by the IDE.

   In conclusion on the issue of performance I haven’t found anything that would suggest that JUL’s performance is not ok compared to the competition.

2. Configuration from classpath. Out-of-the-box JUL cannot load a configuration file from the classpath. It is a few lines of code to make it do so. I can see why this may be annoying but the solution is short and simple.

3. Availability of output handlers. JUL comes with 5 output handlers out-of-the-box: console, file stream, socket and memory. These can be extended or new ones can be written. This may for example be writing to UNIX/Linux Syslog and Windows Event Log. I have personally never had this requirement nor have I seen it used but I can certainly relate to why it may be a useful feature. Logback comes with an appender for Syslog for example. Still I would argue that

   1. 99.5% of the needs for output destinations are covered by what is in JUL out-of-the-box.
   2. Special needs could be catered for by custom handlers on top of JUL rather than on top of something else. There’s nothing to me that suggests that it takes more time to write a Syslog output handler for JUL than it does for another logging framework.

I’m really concerned that there’s something I’ve overlooked. The use of logging facades and logging implementations other than JUL is so widespread that I have to come to the conclusion that it’s me who just doesn’t understand. That wouldn’t be the first time, I’m afraid. 🙂

So what should I do with my API? I want it to become successful. I can of course just “go with the flow” and implement SLF4J (which seems the most popular these days) but for my own sake I still need to understand exactly what is wrong with the JUL of today that warrants all the fuzz? Will I sabotage myself by choosing JUL for my library ?

Testing performance

(section added by nolan600 on 07-JUL-2012)

There’s a reference below from Ceki about SLF4J’s parametrization being 10 times or more faster than JUL’s. So I’ve started doing some simple tests. At first glance the claim is certainly correct. Here are the preliminary results (but read on!):

• Execution time SLF4J, backend Logback: 1515
• Execution time SLF4J, backend JUL: 12938
• Execution time JUL: 16911

The numbers above are msecs so less is better. So 10 times performance difference is by first actually pretty close. My initial reaction: That is a lot !

Here is the core of the test. As can be seen an integer and a string is construted in a loop which is then used in the log statement:

    for (int i = 0; i < noOfExecutions; i++) {
        for (char x=32; x<88; x++) {
            String someString = Character.toString(x);
            // here we log 
        }
    }

(I wanted the log statement to have both a primitive data type (in this case an int) and a more complex data type (in this case a String). Not sure it matters but there you have it.)

The log statement for SLF4J:

logger.info("Logging {} and {} ", i, someString);

The log statement for JUL:

logger.log(Level.INFO, "Logging {0} and {1}", new Object[]{i, someString});

The JVM was ‘warmed up’ with the same test executed once before the actual measurement was done. Java 1.7.03 was used on Windows 7. Latest versions of SLF4J (v1.6.6) and Logback (v1.0.6) was used. Stdout and stderr was redirected to null device.

However, careful now, it turns out JUL is spending most of its time in getSourceClassName() because JUL by default prints the source class name in the output, while Logback doesn’t. So we are comparing apples and oranges. I have to do the test again and configure the logging implementations in a similar manner so that they actually output the same stuff. I do however suspect that SLF4J+Logback will still come out on top but far from the initial numbers as given above. Stay tuned.

Btw: The test was first time I’ve actually worked with SLF4J or Logback. A pleasant experience. JUL is certainly a lot less welcoming when you are starting out.

Testing performance (part 2)

(section added by nolan600 on 08-JUL-2012)

As it turns out it doesn’t really matter for performance how you configure your pattern in JUL, i.e. whether or not it includes the source name or not. I tried with a very simple pattern:

java.util.logging.SimpleFormatter.format="%4$s: %5$s [%1$tc]%n"

and that did not change the above timings at all. My profiler revealed that the logger still spent a lot of time in calls to getSourceClassName() even if this was not part of my pattern. The pattern doesn’t matter.

I’m therefore concluding on the issue of performance that at least for the tested template based log statement there seems to be roughly a factor of 10 in real performance difference between JUL (slow) and SLF4J+Logback (quick). Just like Ceki said.

I can also see another thing namely that SLF4J’s getLogger() call is a lot more expensive than JUL’s ditto. (95 ms vs 0.3 ms if my profiler is accurate). This makes sense. SLF4J has to do some time on the binding of the underlying logging implementation. This doesn’t scare me. These calls should be somewhat rare in the lifetime of an application. The fastness should be in the actual log calls.

Final conclusion

(section added by nolan600 on 08-JUL-2012)

Thank you for all your answers. Contrary to what I initially thought I’ve ended up deciding to use SLF4J for my API. This is based on a number of things and your input:

1. It gives flexibility to choose log implementation at deployment time.

2. Issues with lack of flexibility of JUL’s configuration when run inside an application server.

3. SLF4J is certainly a lot faster as detailed above in particular if you couple it with Logback. Even if this was just a rough test I have reason to believe that a lot more effort has gone into optimization on SLF4J+Logback than on JUL.

4. Documentation. The documentation for SLF4J is simply a lot more comprehensive and precise.

5. Pattern flexibility. As I did the tests I set out to have JUL mimic the default pattern from Logback. This pattern includes the name of the thread. It turns out JUL cannot do this out of the box. Ok, I haven’t missed it until now, but I don’t think it is a thing that should be missing from a log framework. Period!

6. Most (or many) Java projects today use Maven so adding a dependency is not that big a thing especially if that dependency is rather stable, i.e. doesn’t constantly change its API. This seems to be true for SLF4J. Also the SLF4J jar and friends are small in size.

So the strange thing that happened was that I actually got quite upset with JUL after having worked a bit with SLF4J. I still regret that it has to be this way with JUL. JUL is far from perfect but kind of does the job. Just not quite well enough. The same can be said about Properties as an example but we do not think about abstracting that so people can plug in their own configuration library and what have you. I think the reason is that Properties comes in just above the bar while the opposite is true for JUL of today … and in the past it came in at zero because it didn’t exist.