Some ways to log stuff in java

API and configuration

When selecting what logger to use, two things are important. The API and the performance. For the performance it is important that a logging a message should be reasonably fast, but I think it is even more important that not logging a filtered message should be extremely fast, so the cost of extra debug messages should be close to zero in a production environment where debug logging is turned of.

A relevant part of the running time of logging a message might be composing the message by converting some objects to strings and concatenating it all together, so I think a good logging API should make that happen only for actually used messages. Even more importantly, it should be easy and failsafe to get and use a logger.

A simple wrapper

import se.krats.log.LogWrapper;
private static final LogWrapper logger = LogWrapper.forCaller();

logger.info("Something happened with %s by %s", foo, bar);

This is how I think logging should be done. Initializing is one single import and a single static call. I almost always want the category of a logger to be the fully qualified classname of the class logging to it, and since java has no way of saying “this class” statically, I have a named constructor to find out the calling class.

Actually logging a message has the full power and convenience of String.format. The wrapper uses log4j for the actual logging, so see below for configuration.

The only thing wrong with this is creating yet another logging package for java.

slf4j

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
private static final Logger logger = LoggerFactory.getLogger(MyClass.class);

logger.info("Something happened with {} by {}", foo, bar);

Two imports just to get the logger? Ok, I can live with that, I guess.

There is message formatting, so I don’t have to build the string for unused log messages, but there is only one way to format, the n:th {} is replaced with String.valueOf(the n:th argument), so no formatting for numbers or dates or other formatable classes.

Slf4j can use various destination implementations. The default configuration is to use the first destination class it can find on the classpath, so just add slf4j-foo.jar to log to foo.

Java util logging

import java.util.logging.Logger;
import java.util.logging.Level;
final Logger logger = Logger.getLogger(MyClass.class.getName());
final Logger logger_alt = Logger.getLogger("my.package.MyClass");

logger.info("A simple string message");
logger.log(Level.DEBUG, "Something happened with {0} by {1}", new Object[]{foo, bar});

Initialization is almost as good as slf4j, but I normally prefer to get a logger for a class rather than a string. I could use the name of a class as a string constant, but that is very prune to errors when refactoring. I find the risk of using the wrong class is big enough even for the MyClass.class.getName() approach, but that is the same for all implementations except my own wrapper.

Actual logging is somewhat painful. There are methods like logger.debug(msg) and logger.info(msg), but they just take a string argument, and not a format string with arguments. The log method which does take a format and arguments for some reason do not accept a varargs parameter, so an explicit array must be created (there is a method for just one arg, but not two or more).

There doesn’t seem to be a default file name for configuring java util logging from the classpath. Instead, the system property java.util.logging.config.file needs to be set to a file name (absolute or relative to current working directory, not from classpath) for any configuration to be loaded. Otherwise, the default is to log to System.err in a two-line format with American time-stamps.

log4j

import org.apache.log4j.Logger;
private static final Logger logger = Logger.getLogger(LogTimer.class);

logger.info("Something happened with " + foo + " by " + bar);

if (logger.isDebugEnabled()) {
    logger.debug("Something happened with " + foo + " by " + bar);
}

Initialization is simple enough.

Log4j does not provide any formatting, so we have to build the string manually. If we know the message will rarely be actually logged and one of the toString() methods is slow (or the strings are particularly large, putting extra load on the garbage collector), we can query isDebugEnabled() and only log the message when meaningful. But that means a three-line block for a simple debug log, which is probably not gonna happen (so I don’t do it in my test code).

The default place for configuration is a log4j.properties (or xml) on the load-path.

Apache commons

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
private static final Log logger = LogFactory.getLog(LogTimer.class);

logger.info("Something happened with " + foo + " by " + bar);

if (logger.isDebugEnabled()) {
    logger.debug("Something happened with " + foo + " by " + bar);
}

Very similar to log4j, except an extra factory class is needed for initialization. The main problem is the potentially expensive message building for ignored messages, just as for log4j. The same workaround is possible.

Apache commons logging has support for multiple backends. The most commonly used backend is probably log4j, and that is used automatically if available.

Play framework 1.2

import play.Logger;

Logger.info("Something happened with %s by %s", foo, bar);

At first glance, this is very convenient. You don’t even have to have a logger object, just call static debug / info / warn / error methods on the Logger class. And you get the full power of String.format for the messages.

The downside is that there are no separate loggers for different classes, so you can’t use different level filters for different parts of the project and you don’t know what class created a specific message. (Actually, the play logger can record the caller, but that gets very expensive in runtime. I turn this off in my test code).

Performance

To measure the performance of each kind of logger, I wrote a class with a method like this for each logger:

private long measureThisKind() {
    final ThisKindOfLogger logger = InitThisKindOfLogger();
    long start = System.currentTimeMillis();
    for (int i = 0; i < ITER; ++i) {
        logger.info("Message #%d through this kind of logger: %s",
                    i, new LazyFib(i));
        for (int j = 0; j < ITER_DEBUG; ++j) {
            logger.debug("Message #%d,%d through this kind of logger: %s",
                         i, j, new LazyFib(j));
        }
    }
    return System.currentTimeMillis() - start;
}

The exact way of logging an info and a debug message varies with the API for the kind of logger used,

see source for details . The LazyFib object uses a naïve calculating of the (i % MAX_FIB):th fibonacci number as a simple example of a toString method doing something slow.

First, here’s timing stats for what I think is a rather normal usage, with fifty ignored debug messages for each saved info message.

slf4j: 83 ms for 1000 logged and 50000 filtered messages.
my wrap: 117 ms for 1000 logged and 50000 filtered messages.
Log4j: 184 ms for 1000 logged and 50000 filtered messages.
Commons: 189 ms for 1000 logged and 50000 filtered messages.
java.util: 322 ms for 1000 logged and 50000 filtered messages.
Play: 591 ms for 1000 logged and 50000 filtered messages.

Of course, sometimes the wast majority of messages are ignored, in which case the only important thing is to ignore junk messages fast, here even java.util almost shines:

slf4j: 318 ms for 1000 logged and 10000000 filtered messages.
my wrap: 395 ms for 1000 logged and 10000000 filtered messages.
Log4j: 27142 ms for 1000 logged and 10000000 filtered messages.
Commons: 27183 ms for 1000 logged and 10000000 filtered messages.
java.util: 541 ms for 1000 logged and 10000000 filtered messages.
Play: 43684 ms for 1000 logged and 10000000 filtered messages.

But what’s up with play here? Since it has formatting, we would expect ignored messages to be fast, but it is by far the slowest logger in this setup. Indeed, looking in the play source for Logger.debug() we find:

log4j.debug(format(message, args));

So here we have the full cost of String.format formatting (with some extra overhead) even for ignored messages. No wonder it is slow.

For symmetry, here’s a run with no filtered messages at all. Now the nice formatting in my wrap comes at full cost (and the extra stupidity of play doesn’t matter). I don’t know what java.util does to be so slow:

slf4j: 352 ms for 10000 logged and 0 filtered messages.
my wrap: 547 ms for 10000 logged and 0 filtered messages.
Log4j: 242 ms for 10000 logged and 0 filtered messages.
Commons: 243 ms for 10000 logged and 0 filtered messages.
java.util: 1027 ms for 10000 logged and 0 filtered messages.
Play: 529 ms for 10000 logged and 0 filtered messages.

All of the above was with one object with a rather slow toString method in the message (MAX_FIB = 20 in the test code). So, just for fairness, here’s a sample with MAX_FIB=1.

slf4j: 82 ms for 1000 logged and 50000 filtered messages.
my wrap: 115 ms for 1000 logged and 50000 filtered messages.
Log4j: 84 ms for 1000 logged and 50000 filtered messages.
Commons: 85 ms for 1000 logged and 50000 filtered messages.
java.util: 311 ms for 1000 logged and 50000 filtered messages.
Play: 458 ms for 1000 logged and 50000 filtered messages.

slf4j: 298 ms for 1000 logged and 10000000 filtered messages.
my wrap: 366 ms for 1000 logged and 10000000 filtered messages.
Log4j: 1961 ms for 1000 logged and 10000000 filtered messages.
Commons: 2132 ms for 1000 logged and 10000000 filtered messages.
java.util: 593 ms for 1000 logged and 10000000 filtered messages.
Play: 17980 ms for 1000 logged and 10000000 filtered messages.

As you can see, slf4j still takes the lead, even if log4j or commons isn’t far behind when there is few ignored messages.

And for symmetry, here’s a run with MAX_FIB = 35. The most common log messages in a real project won’t be this slow, but in a large project it is not unlikely that some toString methods will be this slow, and I wouldn’t presume to known which ones …

slf4j: 159 ms for 100 logged and 10000 filtered messages.
my wrap: 166 ms for 100 logged and 10000 filtered messages.
Log4j: 14149 ms for 100 logged and 10000 filtered messages.
Commons: 14138 ms for 100 logged and 10000 filtered messages.
java.util: 210 ms for 100 logged and 10000 filtered messages.
Play: 14327 ms for 100 logged and 10000 filtered messages.

Ok, enough of numbers. Feel free to grab the code and vary the parameters. If you add any other loggers to the test, I would apreciate hearing about it.

Conclusion

From now on, I will use slf4j for logging whenever I use java and have the power to choose. And any code that logs "foo: " + foo for a potentially large object foo, as well as any mention at all of java.util.logging or play.Logger, is reason to be careful.

I wont use my wrapper in any real code. Even though slf4j doesn’t provide the full power of String.format, I think the simple formatting it has is enough to avoid using and spreading yet another competing api.