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.

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.

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?

@Ajay Are you doing any logic if logging is turned on, that you do not do when logging is turned off? If not, it should be enough to only run with logging enabled.
–
NicolaiMar 25 '09 at 9:16

@Nicolai. Nope! I dont have any logic inside logging statements. I use cobertura for measuring code/branch coverage. The problem is, cobertura branch coverage expects the junits to run with logging on and another junit with logging off!
–
Ajay NadathurMar 25 '09 at 9:23

4 Answers
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.

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.

+1 to having bugs on the logging code. I've seen more than my share of null pointers when building a string
–
Mario OrtegónMar 25 '09 at 8:02

When running junits, I have enabled logging on all levels. 1. The problem is with the branch coverage. I have to run all junits with log4j enabled and again with log4j disabled. 2. I do a if check inside my Logger class and then only invoke Format.
–
Ajay NadathurMar 25 '09 at 8:28

1

Running your unit tests with and without logging is a good idea anyway. Like Mario says: logs can cause null pointer exceptions and so forth.
–
cletusMar 25 '09 at 10:25

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());
}

with logging on: commons-logging=664ms, Slf4j=559ms, MyLog=3134ms

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.

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.

seriously I am not concerned about branch coverage since I know log calls don't count. But my client really does not agree and you know about QA departments! I will have to place log calls in proper places :)
–
Ajay NadathurMar 25 '09 at 13:42

Wow, you're client is really more concerned about branch coverage than having the most appropriate code? Scary.
–
Jon SkeetMar 25 '09 at 13:49