What is the best practice for debug statements which have string operations in them?

Question

I often find myself adding either concatonated strings or using a string formatter in my debug statements in log4net and log4j should I surround these debug statements with an "if debug" block to stop myself from wasting resources by processing these parameters even though the debug statement will not be printed out?

I would assume that checking if (isDebug) would be quicker and more efficient than having the string operations occuring, however it would lead to the program operating differently (faster) when the debug level is set higher than debug, which could mean that synchronisation problems that happen in production don't happen when I'm writing to the log.

Answer 1

I'd say it depends on how often the debug statement is called and how important performance is. Beware of premature optimization and all.

Answer 2

for Java you can try log5j.

log4j:

log.debug("This thing broke: " + foo + " due to bar: " + bar + " on this thing: " + car);

log5j:

log.debug("This thing broke: %s due to bar: %s on this thing: %s", foo, bar, car);
log.debug("Exception #%d", aThrowable, exceptionsCount++);

Answer 3

Conditional compilation works with final constants, which are static final variables. A class might define the constant like this:

private static final boolean DEBUG = false;

With such a constant defined, any code within an:

if (DEBUG) {
    // code
}

is not actually compiled into the class file. To activate debugging for the class, it is only necessary to change the value of the constant to true and recompile the class (you can have two version of your binaries, one for development and one for production).

However this is solution is suboptimal for several reasons.

Answer 4

I tend to wrap all calls to debug in an isDebug statement. I don't think that's a premature optimization, it's just good practice.

Worrying about the app running at different speeds isn't really sensible, as the load on the processor can / will influence your app more then the debugging code.

Answer 5

Have you measured how much extra time is taken concatenating these strings ? Given that the logging infrastructure will take the resultant messages, check whether they need to be dispatched to (possibly) multiple sinks, and then possibly write using some I/O, then you may not be gaining anything. My feeling is that unless your toString() mechanism is slow, this may be an optimisation too far.

I'm also wary of this approach in case someone writes something like this (and we know they shouldn't but I've seen this before)

if (Log.isDebugEnabled()) {
   Log.debug("Received " + (items++) + " items");
}

and this will then work/fail depending on your logging level.

Answer 6

Try slf4j (http://www.slf4j.org/). You write statements like:

log.fine("Foo completed operation {} on widget {}", operation, widget);

The log message is not assembled inside the library until the log level has been determined to be high enough. I find this the best answer.

(This is a lot like the log5j solution above.)

Answer 7

In log4j the following is recommended best practice:

if ( log.isDebugEnabled() )
{
 log.debug("my " + var + " message";
}

This saves on system resources from the string concatenation etc. You are correct in your assumption that the program may perform slower when debug level is enabled, but that is to be expected: A system under observation is changed because it is under observation. Synchronization issues deal (mostly) with unlucky timing or variable visibility between threads, both of which will not be directly affected by an alteration of the debug level. You will still need to "play" with the system to reproduce multi-threaded problems.

Answer 8

With C#, we've started using delegates for expensive log statements. It's only called if the log level is high enough:

log.Debug(()=> "Getting the value " + SomeValue() " is expensive!");

This prevents logging bugs where the level checked for is different to the level logged at, ie:

if(log.Level == Level.Info)
    log.Debug("Getting the value " + SomeValue() " is expensive!");

and I find it much more readable.

[Edit] If that was downvoted for not applying to Log4Net - it is trivial to write a wrapper around Log4Net to do this.

Answer 9

Look for the externalized log level from log4j config file. That way you have the option to switch on or off logs based on your environment (and avoid all those string concatinations).

if(log.isDebugEnabled()) { log.debug("Debug message"); }

Answer 10

This question is answered in detail in the SLF4J FAQ. In short, use parameterized messages. For example, entry is an object, you can write:

 Object entry = new SomeObject(); 
 logger.debug("The entry is {}.", entry);

After evaluating whether to log or not, and only if the decision is affirmative, will the logger implementation format the message and replace the '{}' pair with the string value of entry. In other words, this form does not incur the cost of parameter construction in case the log statement is disabled.

The following two lines will yield the exact same output. However, the second form will outperform the first form by a factor of at least 30, in case of a disabled logging statement.

  logger.debug("The new entry is "+entry+"."); 
  logger.debug("The new entry is {}.", entry);

Answer 11

We have adopted the practice to define a private static readonly boolean DEBUG variable in each class.

private static readonly log4net.ILogger LOG = log4net.LogManager.GetLogger();
private static readonly bool DEBUG = LOG.IsDebugEnabled;

each actual debug log line looks like this

if (DEBUG) LOG.Debug(...);

where ... can have arbitrary complexity and is only evaluated when debugging is required.

See: http://logging.apache.org/log4net/release/faq.html, the answer to "What is REALLY the FASTEST way of (not) logging?"

This works for us since we only read the log config at startup.

Since we have at least one debug statement per function call, we felt that having to write if (DEBUG) was worth the effort to get maximum performance with debuging switched off. We did some measurements with debugging switched on and off and found performance increases between 10 and 20%. We haven't measured what the effect of the if (DEBUG) was.

By the way: we only do this for debug messages. Warnings, informationals and errors are produced directly via LOG.Warn, etc.