Wednesday, December 09, 2009

Logging needs some lazy evaluation

If it's one situation where lazy evaluation is needed in Java, it's logging. Until something better comes up and we'll have logging injected via AOP or something similar, a log message will be just the result of an extra line in our Java files, and this is a problem.

A normal log message is something like this:

log.fine("Some parameter is:" + someVariable);

This looks quite harmless especially since we know that depending on the log level, our message might be saved or not.

But say we have an expensive function:

log.fine("The extra informations starts at" + reallyLongLastingFunction());

The problem above is obvious: the log string will be built no matter what and our reallyLongLastingFunction() will be called each time, including when the log won't actually be saved.

The solution to this is to pollute your code with something like:

log.fine("The extra informations starts at" + reallyLongLastingFunction());

This way our string creation and expensive function call is done only if the log really is needed. But this adds extra boilerplate in the code as well as makes you maintain the log level (for example what if I change the line to log.finer -- I have to update the if).

If all the log methods would have lazy evaluation this problem would go away -- the code won't be executed until actually needed and there will be only one line in the code.

The AOP style is to inject the logging using bytecode engineering. Perhaps it would be nice to do a post-processing of the resulted JAR artifacts and replace all log calls with something that injects that if check, etc.

And speaking of memory and CPU wasted on logging, there's nothing like seeing that your biggest CPU user is caused by the increased log level while debugging. Debuggers should know how to filter log calls, including time spent in the string building itself otherwise they don't really help.

The case of the different jsch 0.1.54 binaries

As part of the Apache NetBeans IP clearance we are combing through all the code and dependencies. One interesting thing we bumped into wa...