Logging preemption

Question

Extraneous logging can be expensive. Therefore, I could turn off logging or heighten the logging threshold level to reduce logging during production mode (everybody knows that!)

However, what about the routines that are called to supply parameters to the logger statement?

Consider the logger statement.

logger.info("number of windows="+wins.size());

where wins.size() is an excruciatingly expensive operation - say, just for illustration of my (mis)understanding the problem.

If info logging is turned off, would wins.size() still be run.

Because when I do debugging, it seems that wins.size() gets stepped over first before log.info(). If so, what are your strategies to prevent expensive functions inside a logger statement from being executed if the logger is turned off?

Answer 1

You should always check if a logging level is enabled BEFORE logging, esp. if you plan on logging something that requires a particularly expensive computation. Apache's commons-logging for Java allows you to put guards ahead of your code so you could do this:

if (logger.isInfoEnabled()) {
       logger.info("number of windows="+wins.size());
}

If info logging is turned off, wins.size() is guaranteed not to run. You can do similar things with Log4j and the built-in Java logger classes.

Answer 2

In C# 3.0 you could use lambdas to only execute a call to logging function when the logging is turned on. This is example using C# Common.Logging:

Logger.Trace(m=>m("number of windows="+wins.size()));

where Trace is defined like so:

void Trace(Action<FormatMessageHandler> formatMessageCallback);

and FormatMessageHandler is

public delegate string FormatMessageHandler(string format, params object[] args);

So what happens is if tracing is turned on the m=>m("number of windows="+wins.size()) lambda gets called. If it's off, the expensive call to get the window size is never made.

Answer 3

I used a strategy similar to this on a project recently to avoid having to make checks like logger.IsDebugEnabled() everywhere. Essentially, I derived from a base logger implementation and added an extra method that accepted a Closure which invoked the expensive method. Passing in the closure doesn't execute the code until you actually invoke it. Logging should be as aspect-oriented as possible, and it should definitely Just Work without having to make changes across all of your code.

In C# and Ruby, the approach would be similar: pass in a lambda or a block, and defer the execution of the code until it's actually needed at runtime. Win-win!

Answer 4

Modern logging frameworks (like sl4j in the Java world) take a formatting specification and a list of arguments, much like a sprintf call. The message formatted, converting the arguments to strings, only when needed.