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:
"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) "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. "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). "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? "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:
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. 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. 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 99.5% of the needs for output destinations are covered by what is in JUL out-of-the-box. 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:
It gives flexibility to choose log implementation at deployment time. Issues with lack of flexibility of JUL's configuration when run inside an application server. 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. Documentation. The documentation for SLF4J is simply a lot more comprehensive and precise. 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! 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.
InternalLoggerFactory.java
.
java.lang.System.Logger
, which is an interface, which can be redirected to whatever actual logging framework you want, as long as that framework caught up and provides an implementation of that interface. Combined with the modularization, you could even deploy an application with a bundled JRE not containing java.util.logging
, if you prefer a different framework.
Disclaimer: I am the founder of log4j, SLF4J and logback projects.
There are objective reasons for preferring SLF4J. For one, SLF4J allows the end-user the liberty to choose the underlying logging framework. In addition, savvier users tend to prefer logback which offers capabilities beyond log4j, with j.u.l falling way behind. Feature-wise j.u.l may be sufficient for some users but for many others it just isn't. In a nutshell, if logging is important to you, you would want to use SLF4J with logback as the underlying implementation. If logging is unimportant, j.u.l is fine.
However, as an oss developer, you need to take into account the preferences of your users and not just your own. It follows that you should adopt SLF4J not because you are convinced that SLF4J is better than j.u.l but because most Java developers currently (July 2012) prefer SLF4J as their logging API. If ultimately you decide not to care about popular opinion, consider the following facts:
those who prefer j.u.l do so out of convenience because j.u.l is bundled with the JDK. To my knowledge there are no other objective arguments in favor of j.u.l. your own preference for j.u.l is just that, a preference.
Thus, holding "hard facts" above public opinion, while seemingly brave, is a logical fallacy in this case.
If still not convinced, JB Nizet makes an additional and potent argument:
Except the end user could have already done this customization for his own code, or another library that uses log4j or logback. j.u.l is extensible, but having to extend logback, j.u.l, log4j and God only knows which other logging framework because he uses four libraries that use four different logging frameworks is cumbersome. By using SLF4J, you allow him to configure the logging frameworks he wants, not the one you have chosen. Remember that a typical project uses myriads of libraries, and not just yours.
If for whatever reason you hate the SLF4J API and using it will snuff the fun out of your work, then by all means go for j.u.l. After all, there are means to redirect j.u.l to SLF4J.
By the way, j.u.l parametrization is at least 10 times slower than SLF4J's which ends up making a noticeable difference.
java.util.logging was introduced in Java 1.4. There were uses for logging before that. That's why many other logging APIs exist. Those APIs were used heavily before Java 1.4 and thus had a great market share that didn't just drop to zero when 1.4 was release. JUL didn't start out all that great. Many of the things you mentioned were a lot worse in 1.4 and only got better in 1.5 (and I guess in 6 as well, but I'm not too sure). JUL isn't well suited for multiple applications with different configurations in the same JVM (think multiple web applications that should not interact). Tomcat needs to jump through some hoops to get that working (effectively re-implementing JUL if I understood that correctly). You can't always influence what logging framework your libraries use. Therefore using SLF4J (which is actually just a very thin API layer above other libraries) helps keep a somewhat consistent picture of the entire logging world (so you can decide the underlying logging framework while still having library logging in the same system). Libraries can't easily change. If a previous version of a library used to use logging-library-X it can't easily switch to logging-library-Y (for example JUL), even if the latter is clearly superior. Any user of that library would need to learn the new logging framework and (at least) reconfigure their logging. That's a big no-no, especially when it brings no apparent gain to most people.
Having said all that I think JUL is at least a valid alternative to other logging frameworks these days.
IMHO, the main advantage in using a logging facade like slf4j is that you let the end-user of the library choose which concrete logging implementation he wants, rather than imposing your choice to the end user.
Maybe he has invested time and money in Log4j or LogBack (special formatters, appenders, etc.) and prefers continuing using Log4j or LogBack, rather than configuring jul. No problem: slf4j allows that. Is it a wise choice to use Log4j over jul? Maybe, maybe not. But you don't care. Let the end user choose what he prefers.
I started, like you I suspect, using JUL because it was the easiest one to get going immediately. Over the years, however, I have come to wish I had spent a little more time choosing.
My main issue now is that we have a substantial amount of 'library' code that is used in many applications and they all use JUL. Whenever I use these tools in a web-service type app the logging just disappears or goes somewhere unpredictable or strange.
Our solution was to add a facade to the library code that meant that the library log calls did not change but were dynamically redirected to whatever logging mechanism is available. When included in a POJO tool they are directed to JUL but when deployed as a web-app they are redirected to LogBack.
Our regret - of course - is that the library code does not use parameterised logging but this can now be retrofitted as and when needed.
We used slf4j to build the facade.
I ran jul against slf4j-1.7.21 over logback-1.1.7, output to an SSD, Java 1.8, Win64
jul ran 48449 ms, logback 27185 ms for an 1M loop.
Still, a little more speed and a bit nicer API is not worth 3 libraries and 800K for me.
package log;
import java.util.logging.Level;
import java.util.logging.Logger;
public class LogJUL
{
final static Logger logger = Logger.getLogger(LogJUL.class.getSimpleName());
public static void main(String[] args)
{
int N = 1024*1024;
long l = System.currentTimeMillis();
for (int i = 0; i < N; i++)
{
Long lc = System.currentTimeMillis();
Object[] o = { lc };
logger.log(Level.INFO,"Epoch time {0}", o);
}
l = System.currentTimeMillis() - l;
System.out.printf("time (ms) %d%n", l);
}
}
and
package log;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class LogSLF
{
static Logger logger = LoggerFactory.getLogger(LogSLF.class);
public static void main(String[] args)
{
int N = 1024*1024;
long l = System.currentTimeMillis();
for (int i = 0; i < N; i++)
{
Long lc = System.currentTimeMillis();
logger.info("Epoch time {}", lc);
}
l = System.currentTimeMillis() - l;
System.out.printf("time (ms) %d%n", l);
}
}
logger.info()
. So you're deliberately crippling j.u.l. performance to compensate for a shortcoming in slf4j's interface. You should instead code both methods the way they are idiomatically coded.
Success story sharing