Logging complexity and concern about MessageFormat performance.

Question

Hi,
My application uses log4j for logging and usually I do logging by checking whether a particular level is enabled and then log like the following

if(Logger.isApplicationDebugEnabled()){
   Logger.logApplicationDebug("something"+values);  
 }

Now this if check reduces our branch coverage during jUnit testing. In order to overcome this, my friend suggested getting rid of "if" checks for logging.

1. First one of my friends suggested removing the if check and log directly. The problem with this approach is that it might slow down the application due to formation of strings which would not end up in log files anyway.

2. The second approach I thought of was very similar to SLF4j.

   Logger.debug("Number {0}, with date {1,date}",1234, new Date());

This felt very attractive and simple.(This solution internally uses MessageFormat.format(str, object[]) method. But I am concerned about the performance this might have. Also note that 'Logger' is my internal utility class and in each of its log methods, there is a check of Log enabling. What do you guys suggest? I went through velocity templates but it requires map of parameters. Is there any lightweight solution which just substitutes values based on param index location or is this solution okay?

Answer 1

The only way to know is to measure. Guesses about performance are almost always wrong :)

Personally I'd probably just stick with your original log4j code - don't get too hung up about coverage. It's reasonable to guard against making too many log calls for code paths that are always followed - but I wouldn't bother for things like error conditions, where you're already in an odd and hopefully rare situation. Within that, write the most readable code, and then make sure your app performs as well as you need it to. If it doesn't, profile it to find out where the problem is. If it's in the logging code, optimise that.

Answer 2

Ok, I'll ask the obvious question: why not just enable debug logging--or all levels really--while running your unit tests? This has the advantage of increasing code coverage tests AND testing for problems in your logging (which is far from out of the realm of possibility).

The checks on if logging is enabled are there for a reason: it can be expensive (inside big loops) to not only construct the final log string but the individual parameters themselves might be expensive to construct. Using MessageFormat or java.util.Formatter or whatever won't get rid of the second problem. I'd really encourage you to keep the check.

Answer 3

I have actually done what you're suggesting on one project and I have positive experiences with that approach. I created an additional layer over commons-logging that allowed message formatting with MessageFormat under the hood.

These are the results I obtained after measuring pretty much the same usage pattern you describe, 10000 invocations of something like:

    for (int i = 0; i < 10000; i ++) {
        log.debug("Example message: {0} from {1} at {2}!", i, "test", new Date());
    }
  

1. with logging on: commons-logging=664ms, Slf4j=559ms, MyLog=3134ms
2. with logging off: commons-logging=6ms, Slf4j=7ms, MyLog=7ms

Obviously, "MyLog" was considerably slower with debugging output turned on, but up to par with them when when debugging if off. Just to make clear, in "MyLog", I explicitly check for isDebugEnabled() before actually formatting the message.

However, resulting logging code is now way more clearer, and our entire team ends up producing much more useful and detailed messages. Before this, it was not uncommon to have separate methods to construct longer logger messages.

Given that there is virtually no additional performance hit when logging is turned off, I can see myself using this technique in the future.

Answer 4

I can strongly recommend the slf4j facade for log4j which allows you to use this syntax

log.info("Hello {} from {}", "World", "me")

which only does the string expansion after it has been decided that the event should actually should be logged so you don't have to specify the ifEnabled wrapper. Then use log4j as the backend for slf4j.

In addition this has measured to be much faster than the MessageFormatter.