You are viewing a plain text version of this content. The canonical link for it is here.
Posted to common-dev@hadoop.apache.org by Raghu Angadi <ra...@yahoo-inc.com> on 2007/03/29 20:00:04 UTC
Cost of debug statements.
Is there a way to test to if debug is enabled before invoking a
statement like :
NameNode.stateChangeLog.debug(
"BLOCK* NameSystem.UnderReplicationBlock.add:"
+ block.getBlockName()
+ " has only "+curReplicas
+ " replicas and need " + expectedReplicas
+ " replicas so is added to neededReplications"
+ " at priority level " + priLevel );
It looks like we pay the cost of constructing the string for this call
all the time. This seems to involve multiple allocations and
deallocations, int to string conversions, and string concatenations etc.
Since there are multiple such statements in various critical code paths
on namenode, it could affect quite a bit of performance. Should we have
something like :
if ( debugEnabled ) {
NameNode.stateChangeLog.debug( ...
}
Raghu.
Re: Cost of debug statements.
Posted by Doug Cutting <cu...@apache.org>.
Raghu Angadi wrote:
> if ( debugEnabled ) {
> NameNode.stateChangeLog.debug( ...
> }
Yes, this is sometimes warranted. I've also seen it abused, with, e.g.,
guards placed around all log statements. I suggest the following
guidelines:
Guards should only be used:
1. in inner-loop code where performance is known to be critical; and
2. for messages logged at a finer level than default (INFO), i.e.,
only for debug-level messages.
The case you mention seems to meet both of these criteria. +1
Doug
Re: Cost of debug statements.
Posted by Enis Soztutar <en...@gmail.com>.
Doug Cutting wrote:
> Nigel Daley wrote:
>> Just a caveat: when there is conditional code like this
>> based on the configured logging level, then testing
>> should be done with different logging levels to
>> verify that there are no side effects or exceptions
>> (such as NPE) generated by these conditional code
>> blocks. FWIW, this is not something I currently consider
>> in my test matrix.
>
> We could test this by running unit tests at DEBUG, but I also think
> it's fair to declare that we only support running the code at
> particular log levels. Running things at DEBUG level can affect
> timing and scalability, and things probably won't work as reliably in
> all situations, even without bugs in the logging code.
>
> Doug
>
Log4j has is<Level>Enabled() methods to check for a certain debugging
level. However as expected the logging functions such as info() or
debug() also checks for the debugging level being enabled.
A very frequently asked question is why would somebody use the test
is<Level>Enabled before a logging statement, since the function already
checks this. But prior checking avoids argument computation. For example
a statement like
log.debug("start:" + someclass.getStart() + " end:" + someclass.getEnd());
should be guarded by checking the log level, since the string
"start....." will always be computed regardless of debug level being
enabled.
But IMO if the argument to the logging function is straightforward,
there is not need to clutter the code with code guards.
Re: Cost of debug statements.
Posted by Doug Cutting <cu...@apache.org>.
Nigel Daley wrote:
> Just a caveat: when there is conditional code like this
> based on the configured logging level, then testing
> should be done with different logging levels to
> verify that there are no side effects or exceptions
> (such as NPE) generated by these conditional code
> blocks. FWIW, this is not something I currently consider
> in my test matrix.
We could test this by running unit tests at DEBUG, but I also think it's
fair to declare that we only support running the code at particular log
levels. Running things at DEBUG level can affect timing and
scalability, and things probably won't work as reliably in all
situations, even without bugs in the logging code.
Doug
Re: Cost of debug statements.
Posted by Nigel Daley <nd...@yahoo-inc.com>.
Just a caveat: when there is conditional code like this
based on the configured logging level, then testing
should be done with different logging levels to
verify that there are no side effects or exceptions
(such as NPE) generated by these conditional code
blocks. FWIW, this is not something I currently consider
in my test matrix.
Nige
On Mar 29, 2007, at 11:02 AM, Dhruba Borthakur wrote:
> There are portions code in the Namenode:
>
> if (NameNode.stateChangeLog.isInfoEnabled()) {
> ...
> }
>
> -----Original Message-----
> From: Raghu Angadi [mailto:rangadi@yahoo-inc.com]
> Sent: Thursday, March 29, 2007 11:00 AM
> To: hadoop-dev@lucene.apache.org
> Subject: Cost of debug statements.
>
>
> Is there a way to test to if debug is enabled before invoking a
> statement like :
>
> NameNode.stateChangeLog.debug(
> "BLOCK*
> NameSystem.UnderReplicationBlock.add:"
> + block.getBlockName()
> + " has only "+curReplicas
> + " replicas and need " + expectedReplicas
> + " replicas so is added to neededReplications"
> + " at priority level " + priLevel );
>
> It looks like we pay the cost of constructing the string for this call
> all the time. This seems to involve multiple allocations and
> deallocations, int to string conversions, and string concatenations
> etc.
> Since there are multiple such statements in various critical code
> paths
> on namenode, it could affect quite a bit of performance. Should we
> have
> something like :
>
> if ( debugEnabled ) {
> NameNode.stateChangeLog.debug( ...
> }
>
> Raghu.
>
Re: Cost of debug statements.
Posted by Raghu Angadi <ra...@yahoo-inc.com>.
Thanks. There is a isDebugEnabled() also. We should convert many of our
debug statements into this. I will do as I submit patches.
Raghu.
Dhruba Borthakur wrote:
> There are portions code in the Namenode:
>
> if (NameNode.stateChangeLog.isInfoEnabled()) {
> ...
> }
>
> -----Original Message-----
> From: Raghu Angadi [mailto:rangadi@yahoo-inc.com]
> Sent: Thursday, March 29, 2007 11:00 AM
> To: hadoop-dev@lucene.apache.org
> Subject: Cost of debug statements.
>
>
> Is there a way to test to if debug is enabled before invoking a
> statement like :
>
> NameNode.stateChangeLog.debug(
> "BLOCK* NameSystem.UnderReplicationBlock.add:"
> + block.getBlockName()
> + " has only "+curReplicas
> + " replicas and need " + expectedReplicas
> + " replicas so is added to neededReplications"
> + " at priority level " + priLevel );
>
> It looks like we pay the cost of constructing the string for this call
> all the time. This seems to involve multiple allocations and
> deallocations, int to string conversions, and string concatenations etc.
> Since there are multiple such statements in various critical code paths
> on namenode, it could affect quite a bit of performance. Should we have
> something like :
>
> if ( debugEnabled ) {
> NameNode.stateChangeLog.debug( ...
> }
>
> Raghu.
>
RE: Cost of debug statements.
Posted by Dhruba Borthakur <dh...@yahoo-inc.com>.
There are portions code in the Namenode:
if (NameNode.stateChangeLog.isInfoEnabled()) {
...
}
-----Original Message-----
From: Raghu Angadi [mailto:rangadi@yahoo-inc.com]
Sent: Thursday, March 29, 2007 11:00 AM
To: hadoop-dev@lucene.apache.org
Subject: Cost of debug statements.
Is there a way to test to if debug is enabled before invoking a
statement like :
NameNode.stateChangeLog.debug(
"BLOCK* NameSystem.UnderReplicationBlock.add:"
+ block.getBlockName()
+ " has only "+curReplicas
+ " replicas and need " + expectedReplicas
+ " replicas so is added to neededReplications"
+ " at priority level " + priLevel );
It looks like we pay the cost of constructing the string for this call
all the time. This seems to involve multiple allocations and
deallocations, int to string conversions, and string concatenations etc.
Since there are multiple such statements in various critical code paths
on namenode, it could affect quite a bit of performance. Should we have
something like :
if ( debugEnabled ) {
NameNode.stateChangeLog.debug( ...
}
Raghu.