harmony-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Alex Blewitt" <alex.blew...@gmail.com>
Subject Re: [classlib] logging from within our implementation
Date Wed, 31 May 2006 08:27:29 GMT
On 31/05/06, Chris Gray <chris.gray@kiffer.be> wrote:
> On Tuesday 30 May 2006 23:38, Alex Blewitt wrote:
> >
> > Not necessarily. Evaluation of arguments may have side-effects, and
> > therefore even if the call to the logging gets optimised away, the
> > evaluation may not be.
>
> You're right, and the more I look at it the less likely it seems to me that
> the evaluation of parameters will be optimised away. To start with string
> concatenation: the expression ("hello " + "world") has no side-effects...

True. That's why a decent logging API doesn't just take a single
String, but can take an arbitrary number of them (or even better,
Objects). So you'd be able to do logger.info(["Hello","World"]); and
only when the logging is being performed would it need to do the
concatenation (or more likely, just two print statements). The only
problem is you'd still have the construction time of the array; I
don't know if the VARARGs implementation would solve that.

Even better, if it takes objects, you don't even need to do the
.toString() operation until you know you need it as a string.

On 31/05/06 Someone Else Wrote:
> j.u.l logging is well designed, and if used correctly, has minimal performance
> penalty, since unused logging directives are simply wiped out by optmimizing Jit.

I don't think anyone I've met thinks that j.u.l logging is well
designed. It was a bodge job that took some ideas from log4j and then
did its own thing. And unlike log4j, it could only be run on 1.4+
systems. And both of those tend to prefer having a single String
message in their arguments, with the result that everyone does a
string concatenation in their logging message (although there is a
parameterised message format, it doesn't tend to be used because it's
more verbose in calling code).

And the logging directives are *not* wiped out by an optimizing Jit.
Even if it's intelligent enough to know that the method it's calling
is a no-op, it can't guarantee that the evaluation of the arguments
have no side effects. I worked on a project once where there were
debug log statements liberally sprinkled through the code, where
messages (often large ones, as toString() are wont to create). The
issue was, the system ran like a dog even when debug logging was
disabled. The problem was that even though the log.debug(String)
wasn't doing anything, the largeObject.toString() *was* and eating up
a bunch of memory/processor for no good reason.

They removed the debugging statements, and it ran so fast that they
discovered all kinds of race conditions that they hadn't designed for.
So they had to put the debugging statements back in to slow it down
before shipping it to the customer :-) Mind you, I expect that
marketing would have jumped on the bandwaggon with 2.0! Much faster
than 1.0! but I didn't hang around long enough there to find out :-)

You've also got to take into account that no matter how clever people
think they are when using a StringBuffer in a toString() method, as
soon as you get a collection of objects, you end up with n+1
StringBuffers (one for each object's toString, and one for the
collection itsef).

If you're ever doing performant logging, it's much better to have a
toString(StringBuffer) method that allows you to pass-through a
StringBuffer into the object you want. You can even stub the
toString() to create a new StringBuffer and pass it into the
parameterised version to save doing it in many places.

Moral 1: saying 'It's OK, debug logging can be turned off and
log.debug(msg) is inexpensive' is a lie. If you really feel the need
for sprinkling debug statements everywhere (and I'm with others in
using a good IDE to track down problems) then surround every debug
with if (log.debugEnabled()) { log.debug(msg) }. Yes, it has the same
effect, but at least you don't bother wasting the calcuation of the
message itself, and in this case, even a dozy JIT can optimise it
away.

Moral 2: logging is expensive; toString() doubly so. Much better to
pass in an object (whether that's a StringBuffer or an OutputStream or
a Writer doesn't really matter) so that the toString() method can
append information as it goes, rather than creating lots of strings as
is the case with any kind of compound object.

Moral 3: If you're going to design a multi-threaded system, think
about race conditions first :-)

Alex.

---------------------------------------------------------------------
Terms of use : http://incubator.apache.org/harmony/mailing.html
To unsubscribe, e-mail: harmony-dev-unsubscribe@incubator.apache.org
For additional commands, e-mail: harmony-dev-help@incubator.apache.org


Mime
View raw message