hi guys,

We have been using log4j in our j2ee project. We are now worried about runtime overhead.

For eg.

   if(logger.isDebugEnabled()) {
     logger.debug("Debug Message: " + i);
   }

With the first "if" condition, We avoid the message construction for logging if the debug is disabled. But still we have to go through a condition checking.

Therefore we have planned to include something like "C" preprocessing.

//#ifdef debug
 logger.debug("Debug Message: " + i);
//#endif

 And our source code will go through a parser which removes the logger statement from the source. Is this a good idea ?

Thanks,
Shreedhar

remove the if statement as the logger is surpressed from the log4j.properties file

package example

class X {

   public X( )
   {
      logger = Logger.getLogger( X.class );
      logger.debug( "Hello" );
    }
}

in the log4j.properties

log4j.logger.example = info

and the log value is never reported to the logger cos of the level

The if condition is introduced to avoid message construction even when the appender level is set to info. By introducing the if condition we can avoid the message construction when the appender level is set to info. Saves some processing yeah.
Reference: http://jakarta.apache.org/log4j/docs/FAQ.html#fastLogging

logger.debug will suppress the message -> true. But internally there will be a checking, which is the one what we are trying to avoid. That is why we are planning something like a pre-processing. Any feedback will be highly helpfull.

Thanks,
Shreedhar

It is a good idea, assuming you are already building externally (with Ant or something like it).

And, instead of going for a "C" like preprocessor, you could go for the real thing. C compilers usually have a switch to just preprocess source files.

If a "public static final boolean" flag on Logger (call it "ENABLED") is used in an "if ()" statement, then it will do exactly what you want:

if (Logger.ENABLED) {
  // any code here, including the if itself, will be
  // completely compiled out if ENABLED==false, and
  // the "if" evaluation will be in-lined if ENABLED==true
}

You can find the supporting details in the Java Language Specifiction.

Note that it requires a full recompile of everything to change the flag from true to false or vice-versa, because these are compile-time optimizations.

Peace,

Cameron Purdy
Tangosol, Inc.
Coherence: Easily share live data across a cluster!

1) Do not use a preprocessor This introduces more complexity into an allready complex deployment process (J2EE)

2) The cost of logging is not in the checking or building of a message it is in the IO so use the features of log4j via the log level

logger.debug("Debug Message: " + i);

uses no more cycles than

if(logger.isDebugEnabled()) {
     logger.debug("Debug Message: " + i);
   }
 
except for constructing the string which is pretty efficient compared to real J2EE bottlenecks.

It may pay dividends if you write debug out everything and the kitchen sink making your code unreadable and even more buggy in some cases

bug example
Object a = null

logger.debug(a.toString());

I have come accross this one in production many times.



You will find very little performance gain from doing this. J2EE applications are inherently IO bound (database disk etc.). The relative gains from concentration on you logging efficiency beyond what is built into log4j is not worth the effort. In allmost all cases I have come accross.


3) remove debug statements in production code all together and use JPDA debugger to attach to your J2EE server and write good unit tests.. it will pay far bigger dividends

Dan D.

I've worked on projects where the construction of the logging strings has definitely had a major impact on performance!

A third-party product was using a log4j logging implementation, and had put stack loads of debug statements in. They of course configured it to be turned off, but the construction of the logging messages was so severe that it was causing a huge amount of memory usage and in the end garbage collection. Fair enough the String concatenation isn't that much of a hit, but combined with garbage collection it can be a killer!

Fair enough, for most systems you will be IO bound, but when you're faced with strict SLAs, every little thing can count in the end.

As an answer to the original posters question, it sounds a fair strategy, although perhaps overly complicated. If you're going to have to recompile to change the logging level, a cleaner way may well be as one of the previous posters stated - use a static final variable and if set to false, the compiler will ignore the code during compilation.

Nice, everyones on the same page here.

So in our system , we actually use the if block to verify if the Debugging truned on or not before we get into the Message construction part. If you weigh the two operations the overhead of the if check is negligable compared to the message generation. So my take was to go with it. From a debugging standpoint , attaching to a live process in a production environment with JPDA was a stretch for me, So what I did was to expose the logging infrastructures configuration through JMX and control the Logging through it. This way I can dynamically turn it on and off in a production system , if I feel its going south.

This is just one school of thought and there are no hard and fast rules in the game IMHO.

Constructing the String can be a bottleneck too. For example we have an application that had a lot of debugging output, including a lot of calls to toString() methods. We found out that these toString() calls took about 3% of CPU time, even when debugging log was disabled. Our solution was to have a LoggerHelper class with a method like this: debug(String message, Object[] params). The params are the objects with the toString() methods. Inside this method we use the suggested code:

debug(String message, Object param){
  if(logger.isDebugEnabled()) {
    logger.debug(message + " [" + param + "]");
  }
}

The advantage is that the toString() is only called when it is actually logged and that we don't need all this code in every single place we log.

Kind regards,

Andreas Berg
Triona