You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@geronimo.apache.org by Mark Mahieu <ma...@twistedbanana.demon.co.uk> on 2003/08/13 01:01:34 UTC
Logging code and Garbage Collection
All,
I know this is a tad early to comment on the code in CVS, but I've just
noticed code like this (in
org.apache.geronimo.deployment.scanner.DeploymentScanner)
log.debug("Finished scan of " + url + ", " + result.size() + "
deployment(s) found");
Could everyone make sure that log statements are wrapped (eg.):
if (log.isDebugEnabled()) {
log.debug("Finished scan of " + url + ", " + result.size() + "
deployment(s) found");
}
The reason being that while profiling a J2EE application a while back we
found that well over 50% of the processors' time was spent executing log
statements just like the above - most of that with the VM messing around
creating StringBuffer objects and then garbage collecting them. In the
case above, this will happen regardless of the logging level in use i.e.
*even if* debug messages aren't actually being output.
A couple of cavaeats:
1) The code above is only executed periodically, so it's not really a
great example of a performance killer ;-)
2) Sun's 1.4.2 VM may be better at mitigating this problem than the one
I was profiling (1.3.1). Still, not everyone will use Sun's VM.
I know this sounds incredibly picky at this stage but I think it'd be an
idea to get into good habits now rather than later. If others agree
with the above, I'll add it to the coding standards in the Wiki.
Mark
RE: Logging code and Garbage Collection
Posted by Jeremy Boynes <je...@coredevelopers.net>.
> I'd say add it to the coding standards. Many people may not even be
> aware that there is such an issue, and having things overspecified in
> the coding standards is more likely to produce better results than
> those which are underspecified.
>
Doing that now...
Re: Logging code and Garbage Collection
Posted by Alex Blewitt <Al...@ioshq.com>.
> I know this is a tad early to comment on the code in CVS, but I've
> just noticed code like this (in
> org.apache.geronimo.deployment.scanner.DeploymentScanner)
>
> log.debug("Finished scan of " + url + ", " + result.size() + "
> deployment(s) found");
>
> Could everyone make sure that log statements are wrapped (eg.):
>
> if (log.isDebugEnabled()) {
> log.debug("Finished scan of " + url + ", " + result.size() + "
> deployment(s) found");
> }
>
> The reason being that while profiling a J2EE application a while back
> we found that well over 50% of the processors' time was spent
> executing log statements just like the above - most of that with the
> VM messing around creating StringBuffer objects and then garbage
> collecting them. In the case above, this will happen regardless of
> the logging level in use i.e. *even if* debug messages aren't actually
> being output.
I agree completely. In fact, I've also been party to one such
application that used this style of logging so badly that their
application crawled. The problem was, when they put the conditional log
statements in the application ran so fast that it showed up all their
syncronization holes in the multi-threading parts of the code.
They put the log stuff back so that it ran slower to avoid debugging
the multi-threaded spaghetti. :-)
> I know this sounds incredibly picky at this stage but I think it'd be
> an idea to get into good habits now rather than later. If others
> agree with the above, I'll add it to the coding standards in the Wiki.
I'd say add it to the coding standards. Many people may not even be
aware that there is such an issue, and having things overspecified in
the coding standards is more likely to produce better results than
those which are underspecified.
Alex.
Re: Logging code and Garbage Collection
Posted by Hiram Chirino <hi...@coredevelopers.net>.
I follow these rules when I log messages:
- Use isTraceEnabled() for all trace messages.
- If I trace more than once in a variable, I cache isTraceEnabled() in a
local variable.
- Use debug level message for messages that get displayed a constant or
a small number of times (component is starting/stopping) etc.
Since only a small number of debug messages should be produced I don't
guard them with isDebugEnabled().
Just my 2 cents.
Regard,
Hiram
On Wed, 2003-08-13 at 03:00, Jason Dillon wrote:
> In general I agree, trace and debug logs should be guarded.
>
> +1
>
> --jason
>
>
> On Wednesday, August 13, 2003, at 06:01 AM, Mark Mahieu wrote:
>
> > All,
> >
> > I know this is a tad early to comment on the code in CVS, but I've
> > just noticed code like this (in
> > org.apache.geronimo.deployment.scanner.DeploymentScanner)
> >
> > log.debug("Finished scan of " + url + ", " + result.size() + "
> > deployment(s) found");
> >
> > Could everyone make sure that log statements are wrapped (eg.):
> >
> > if (log.isDebugEnabled()) {
> > log.debug("Finished scan of " + url + ", " + result.size() + "
> > deployment(s) found");
> > }
> >
> > The reason being that while profiling a J2EE application a while back
> > we found that well over 50% of the processors' time was spent
> > executing log statements just like the above - most of that with the
> > VM messing around creating StringBuffer objects and then garbage
> > collecting them. In the case above, this will happen regardless of
> > the logging level in use i.e. *even if* debug messages aren't actually
> > being output.
> >
> > A couple of cavaeats:
> > 1) The code above is only executed periodically, so it's not really a
> > great example of a performance killer ;-)
> > 2) Sun's 1.4.2 VM may be better at mitigating this problem than the
> > one I was profiling (1.3.1). Still, not everyone will use Sun's VM.
> >
> > I know this sounds incredibly picky at this stage but I think it'd be
> > an idea to get into good habits now rather than later. If others
> > agree with the above, I'll add it to the coding standards in the Wiki.
> >
> > Mark
> >
--
/**************************
* Hiram Chirino
* Partner
* Core Developers Network
**************************/
Re: Logging code and Garbage Collection
Posted by Jason Dillon <ja...@coredevelopers.net>.
In general I agree, trace and debug logs should be guarded.
+1
--jason
On Wednesday, August 13, 2003, at 06:01 AM, Mark Mahieu wrote:
> All,
>
> I know this is a tad early to comment on the code in CVS, but I've
> just noticed code like this (in
> org.apache.geronimo.deployment.scanner.DeploymentScanner)
>
> log.debug("Finished scan of " + url + ", " + result.size() + "
> deployment(s) found");
>
> Could everyone make sure that log statements are wrapped (eg.):
>
> if (log.isDebugEnabled()) {
> log.debug("Finished scan of " + url + ", " + result.size() + "
> deployment(s) found");
> }
>
> The reason being that while profiling a J2EE application a while back
> we found that well over 50% of the processors' time was spent
> executing log statements just like the above - most of that with the
> VM messing around creating StringBuffer objects and then garbage
> collecting them. In the case above, this will happen regardless of
> the logging level in use i.e. *even if* debug messages aren't actually
> being output.
>
> A couple of cavaeats:
> 1) The code above is only executed periodically, so it's not really a
> great example of a performance killer ;-)
> 2) Sun's 1.4.2 VM may be better at mitigating this problem than the
> one I was profiling (1.3.1). Still, not everyone will use Sun's VM.
>
> I know this sounds incredibly picky at this stage but I think it'd be
> an idea to get into good habits now rather than later. If others
> agree with the above, I'll add it to the coding standards in the Wiki.
>
> Mark
>
Re: Logging code and Garbage Collection
Posted by Jens Schumann <je...@void.fm>.
On 8/13/03 01:01 AM Mark Mahieu <ma...@twistedbanana.demon.co.uk> wrote:
> All,
>
> The reason being that while profiling a J2EE application a while back we
> found that well over 50% of the processors' time was spent executing log
> statements just like the above - most of that with the VM messing around
> creating StringBuffer objects and then garbage collecting them. In the
> case above, this will happen regardless of the logging level in use i.e.
> *even if* debug messages aren't actually being output.
>
You may fix the object creation issue but may leave the false impression of
being safe. See recent post from Eric on axis-dev
http://marc.theaimsgroup.com/?l=axis-dev&m=106071965108031&w=2.
Jens