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
-
logger runtime overhead (8 messages)
- Posted by: Shreedhar Natarajan
- Posted on: March 19 2003 01:42 EST
Threaded Messages (8)
- logger runtime overhead by stephen smithstone on March 19 2003 04:05 EST
- logger runtime overhead by Shreedhar Natarajan on March 19 2003 06:28 EST
- logger runtime overhead by Ferhat SAVCI on March 19 2003 06:57 EST
- just like C by Cameron Purdy on March 19 2003 09:42 EST
- To much effort for not much gain by Daniel Davison on March 19 2003 11:32 EST
- To much effort for not much gain by Simon Knott on March 20 2003 11:37 EST
- To much effort for not much gain by Rajesh Natarajan on March 24 2003 04:36 EST
- To much effort for not much gain by Andreas Berg on March 25 2003 09:30 EST
- To much effort for not much gain by Simon Knott on March 20 2003 11:37 EST
-
logger runtime overhead[ Go to top ]
- Posted by: stephen smithstone
- Posted on: March 19 2003 04:05 EST
- in response to Shreedhar Natarajan
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 -
logger runtime overhead[ Go to top ]
- Posted by: Shreedhar Natarajan
- Posted on: March 19 2003 06:28 EST
- in response to stephen smithstone
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 -
logger runtime overhead[ Go to top ]
- Posted by: Ferhat SAVCI
- Posted on: March 19 2003 06:57 EST
- in response to Shreedhar Natarajan
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. -
just like C[ Go to top ]
- Posted by: Cameron Purdy
- Posted on: March 19 2003 09:42 EST
- in response to Shreedhar Natarajan
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! -
To much effort for not much gain[ Go to top ]
- Posted by: Daniel Davison
- Posted on: March 19 2003 11:32 EST
- in response to Shreedhar Natarajan
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. -
To much effort for not much gain[ Go to top ]
- Posted by: Simon Knott
- Posted on: March 20 2003 11:37 EST
- in response to Daniel Davison
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. -
To much effort for not much gain[ Go to top ]
- Posted by: Rajesh Natarajan
- Posted on: March 24 2003 16:36 EST
- in response to Simon Knott
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. -
To much effort for not much gain[ Go to top ]
- Posted by: Andreas Berg
- Posted on: March 25 2003 09:30 EST
- in response to Daniel Davison
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