You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@geronimo.apache.org by Alex Blewitt <Al...@ioshq.com> on 2003/08/14 10:14:50 UTC
[Logs] Re: Logging code and Garbage Collection
On Thursday, Aug 14, 2003, at 06:31 Europe/London, Pasi Salminen wrote:
> Putting my administrator hat on, I must say that I don't like
> application servers
> which do not enable change of logging level at runtime.
Though personally I've not come across this before, I can see that it
would be a desirable thing to have.
> Berin Loritsch wrote:
>
>> For example:
>>
>> if ( m_logger.isDebugEnabled() )
>> {
>> m_logger.debug( "test message" );
>> }
>>
>> is both slower and more cumbersome than this:
>>
>> m_logger.debug( "test message" );
I will agree that there is more code. But bear in mind that w/o the
debugging guard, the m_logger.debug("message") will almost certainly
call m_logger.isDebugEnabled() (or access the boolean to do the test)
anyway, so in the (common) case when debugging isn't enabled then IMHO
it will make very little difference; possibly even run /faster/ with
the guard.
Bear in mind that 'is slower' and 'is faster' are only likely to be
based on what we humans think; until you've actually got code that is
running, and it is demonstrable that this is where the bottleneck is,
then pre-optimisation isn't worthwhile.
Alex.
Re: [Logs] Re: Logging code and Garbage Collection
Posted by Dain Sundstrom <da...@coredevelopers.net>.
On Thursday, August 14, 2003, at 05:34 PM, James Strachan wrote:
> Just to be clear - if I understand Dain's patch correctly - it
> optimises isXEnabled() calls by caching the value in an instance
> variable inside the Log proxy so the JVM can inline it - rather than
> the slightly expensive internal call to a singleton which uses
> synchronization in log4j..
I don't think the method I wrote can be inlined as it accesses private
variables in the log. We could make the variables public as the worst
case is someone changes the values and they are out of whack until the
next update cycle.
> It comes from the discussions of isXEnabled() methods being slow in
> Axis etc.
I don't know about axis but the isXEnabled calls are expensive and this
helps to reduce the sheer number of calls.
-dain
Re: [Logs] Re: Logging code and Garbage Collection
Posted by James Strachan <ja...@yahoo.co.uk>.
Just to be clear - if I understand Dain's patch correctly - it
optimises isXEnabled() calls by caching the value in an instance
variable inside the Log proxy so the JVM can inline it - rather than
the slightly expensive internal call to a singleton which uses
synchronization in log4j..
It comes from the discussions of isXEnabled() methods being slow in
Axis etc.
On Thursday, August 14, 2003, at 11:26 pm, Dain Sundstrom wrote:
> On Thursday, August 14, 2003, at 05:08 PM, Alex Blewitt wrote:
>
>> I fear that this is a tad pointless; the logs in Log4J are going to
>> do this anyway, and not cache the log values.
>
> I disagree that this is pointless. We need something for today (it
> took about a half hour), and when they get their stuff working, we
> remove my code.
>
>> The big problem was that when doing log("String" + value + "message")
>> is that the string concatenation is always done, regardless of
>> whether the log level was enabled or not. That is why it was
>> desirable to surround with the if() statements in the first place ...
>
> Duh. We all agree on that. But when you have debug("my single string
> message") there is not need to wrap, and when you do need the
> isDebugEnabled() call, it will be very fast.
>
>> So the problem is still going to exist, albeit a factor slower since
>> it's going through this caching log :-/
>
> Agree, that is what caching is all about.
>
> -dain
>
>
James
-------
http://radio.weblogs.com/0112098/
Re: [Logs] Re: Logging code and Garbage Collection
Posted by Dain Sundstrom <da...@coredevelopers.net>.
On Friday, August 15, 2003, at 07:54 AM, Berin Loritsch wrote:
> Dain Sundstrom wrote:
>> 1) cache the value and invalidate based on a notification from the
>> logging framework
>> 2) cache the value and invalidate on an interval bases
>> Agreed?
>
>
> :/ Hmm. What about using lastModified() semantics. If the value has
> not
> been modified in X number of minutes, then we can recheck the old
> implementation
> of the isXEnabled. The solution does not eat up a thread to do the
> check.
I thought about that, but I thought that making a System call to get
the current time is a fairly expensive operation to do on every call.
I would have listed it as an option, but I consider it an
implementation of option 2.
>> BTW here is my justification. isDebugEnabled looks like this:
>> public boolean isDebugEnabled() {
>> if (repository.isDisabled(Level.DEBUG_INT)) {
>> return false;
>> }
>> return Level.DEBUG.isGreaterOrEqual(this.getEffectiveLevel());
>> }
>
>
> That's only one implementation. It might be better to fix Log4J. BTW,
> how does JDK 1.4 Logging work?
I agree it would be better to get this into Log4j, and I have heard
that they are working on this. As I said before when they do fix it,
we can remove my class.
> <snip type="code">
>
>> According to the extensive testing Jeremy and I did on the fastest
>> way to implement the locking system, the most expensive thing in raw
>> java is volatile variables. It was actually faster to synchronize
>> and get the value, but that may reduce concurrency. This was not a
>> problem for locking as it is designed to control concurrency. My
>> code on the other hand, caches the value of this expensive call and
>> keeps it in an non-synchronized non-volatile variable. At noted in
>> the code this is OK because boolean assignment is atomic and at the
>> worst case we will have running threads with an outdated processor
>> cache of the value, which is OK as this is designed to be an out of
>> date cache. So unless you turn off debug for the entire hierarchy
>> there is no way my code can be slower and if you have turned it off
>> for the entire hierarchy, my code should be no slower.
>
> Category is for an old version of Log4J, does this problem still exist
> in
> the new code?
Check the code... Logger extends Category where all of the
functionality exists, so yes the problem still exists.
> Anyway, I'm not trying to ruffle feathers, but just point out that the
> same thing can be done without eating up precious resources like
> Threads.
Sure, this is one of the possible tradeoffs to alleviate (not fix) the
problem, and with all things in engineering there are many other
tradeoffs we could take.
-dain
Re: [Logs] Re: Logging code and Garbage Collection
Posted by Berin Loritsch <bl...@apache.org>.
Dain Sundstrom wrote:
> Man did you have me pissed off when I read this. You almost got a
> flaming response, but I trashed it and you are getting this one...
>
>
> Alex,
>
> I boil the issue down as follows, excessive calls to isXEnable is bad
> because of the excessive overhead.
>
> Agreed?
IMO, its too early to tell on this point. Those calls will be made
regardless of whether we do it explicitly or not. Anyhoo, it really
isn't worth wasting breath arguing about the issue. At this point,
if you are absolutely convinced that the isXEnabled check must be
cached, then we might as well do it the best way.
>
> 1) cache the value and invalidate based on a notification from the
> logging framework
> 2) cache the value and invalidate on an interval bases
>
> Agreed?
:/ Hmm. What about using lastModified() semantics. If the value has not
been modified in X number of minutes, then we can recheck the old implementation
of the isXEnabled. The solution does not eat up a thread to do the check.
>
> BTW here is my justification. isDebugEnabled looks like this:
>
> public boolean isDebugEnabled() {
> if (repository.isDisabled(Level.DEBUG_INT)) {
> return false;
> }
> return Level.DEBUG.isGreaterOrEqual(this.getEffectiveLevel());
> }
That's only one implementation. It might be better to fix Log4J. BTW,
how does JDK 1.4 Logging work?
<snip type="code">
> According to the extensive testing Jeremy and I did on the fastest way
> to implement the locking system, the most expensive thing in raw java is
> volatile variables. It was actually faster to synchronize and get the
> value, but that may reduce concurrency. This was not a problem for
> locking as it is designed to control concurrency. My code on the other
> hand, caches the value of this expensive call and keeps it in an
> non-synchronized non-volatile variable. At noted in the code this is OK
> because boolean assignment is atomic and at the worst case we will have
> running threads with an outdated processor cache of the value, which is
> OK as this is designed to be an out of date cache. So unless you turn
> off debug for the entire hierarchy there is no way my code can be slower
> and if you have turned it off for the entire hierarchy, my code should
> be no slower.
Category is for an old version of Log4J, does this problem still exist in
the new code?
Anyway, I'm not trying to ruffle feathers, but just point out that the
same thing can be done without eating up precious resources like Threads.
--
"They that give up essential liberty to obtain a little temporary safety
deserve neither liberty nor safety."
- Benjamin Franklin
Re: [Logs] Re: Logging code and Garbage Collection
Posted by Dain Sundstrom <da...@coredevelopers.net>.
Man did you have me pissed off when I read this. You almost got a
flaming response, but I trashed it and you are getting this one...
Alex,
I boil the issue down as follows, excessive calls to isXEnable is bad
because of the excessive overhead.
Agreed?
There are two solutions to this problem (notice both involve caching
the value):
1) cache the value and invalidate based on a notification from the
logging framework
2) cache the value and invalidate on an interval bases
Agreed?
Since as far as I recall, the log4j production release does not send
notifications we can not do option 1. Option 2 is easy and simple. It
took literally 20 minutes to write and test.
Now you seem to be arguing that this code will not be faster, and is a
complete waste of effort and will only make geronimo harder to
maintain. If this is not your point please clarify. If it is, can you
tell me how this code would *ever* be slower unless the interval is too
aggressive (currently 3 minutes).
BTW here is my justification. isDebugEnabled looks like this:
public boolean isDebugEnabled() {
if (repository.isDisabled(Level.DEBUG_INT)) {
return false;
}
return Level.DEBUG.isGreaterOrEqual(this.getEffectiveLevel());
}
This says that if your log hierarchy has debug enabled at all then call
getEffectiveLevel which has the following code:
public Level getEffectiveLevel() {
for (Category c = this; c != null; c = c.parent) {
if (c.level != null) {
return c.level;
}
}
return null; // If reached will cause an NullPointerException.
}
If you take a look at level it is defined as follows:
protected volatile Level level;
According to the extensive testing Jeremy and I did on the fastest way
to implement the locking system, the most expensive thing in raw java
is volatile variables. It was actually faster to synchronize and get
the value, but that may reduce concurrency. This was not a problem for
locking as it is designed to control concurrency. My code on the other
hand, caches the value of this expensive call and keeps it in an
non-synchronized non-volatile variable. At noted in the code this is
OK because boolean assignment is atomic and at the worst case we will
have running threads with an outdated processor cache of the value,
which is OK as this is designed to be an out of date cache. So unless
you turn off debug for the entire hierarchy there is no way my code can
be slower and if you have turned it off for the entire hierarchy, my
code should be no slower.
At this point, I am going to stop posting to this thread, because this
type of detailed justification for such a small non-critical, zero
impact commit eating up all of my development time.
-dain
Re: [Logs] Re: Logging code and Garbage Collection
Posted by James Strachan <ja...@yahoo.co.uk>.
On Thursday, August 14, 2003, at 11:59 pm, Alex Blewitt wrote:
>>> So the problem is still going to exist, albeit a factor slower since
>>> it's going through this caching log :-/
>>
>> Agree, that is what caching is all about.
>
> Sorry, my point was that I expected your caching code to slow it down;
> IMHO it will run faster without it. Caching a boolean value is an
> incredibly small factor of performance boost, and you've got an extra
> method call in your chain. When I was playing around with benchmarks,
> the method call was the expensive bit, not the boolean value access.
Alex - why don't you write a little performance benchmark test & submit
it then we can put this matter to an end.
James
-------
http://radio.weblogs.com/0112098/
Re: [Logs] Re: Logging code and Garbage Collection
Posted by Alex Blewitt <Al...@ioshq.com>.
Have you tested this to find out how much performance you save by doing
this? If there's not any numbers to show how well it is before and
after, and that it was in the bottleneck of the system, then it's
premature optimisation.
On Thursday, Aug 14, 2003, at 23:26 Europe/London, Dain Sundstrom wrote:
> On Thursday, August 14, 2003, at 05:08 PM, Alex Blewitt wrote:
>
>> I fear that this is a tad pointless; the logs in Log4J are going to
>> do this anyway, and not cache the log values.
>
> I disagree that this is pointless. We need something for today (it
> took about a half hour), and when they get their stuff working, we
> remove my code.
I didn't know it was broken, my mistake.
>> The big problem was that when doing log("String" + value + "message")
>> is that the string concatenation is always done, regardless of
>> whether the log level was enabled or not. That is why it was
>> desirable to surround with the if() statements in the first place ...
>
> Duh. We all agree on that. But when you have debug("my single string
> message") there is not need to wrap, and when you do need the
> isDebugEnabled() call, it will be very fast.
I think the consensus was to always use isDebugEnabled() anyway, and if
it is being used more than once in a method then it is held in a local
variable, as opposed to having a caching framework ...
>> So the problem is still going to exist, albeit a factor slower since
>> it's going through this caching log :-/
>
> Agree, that is what caching is all about.
Sorry, my point was that I expected your caching code to slow it down;
IMHO it will run faster without it. Caching a boolean value is an
incredibly small factor of performance boost, and you've got an extra
method call in your chain. When I was playing around with benchmarks,
the method call was the expensive bit, not the boolean value access.
So, if you've got numbers to say that this makes a noticeable
difference in a big piece of code and that it helps the bottleneck,
great. But if not, we may not need to use it.
Alex.
Re: [Logs] Re: Logging code and Garbage Collection
Posted by Dain Sundstrom <da...@coredevelopers.net>.
On Thursday, August 14, 2003, at 05:08 PM, Alex Blewitt wrote:
> I fear that this is a tad pointless; the logs in Log4J are going to do
> this anyway, and not cache the log values.
I disagree that this is pointless. We need something for today (it
took about a half hour), and when they get their stuff working, we
remove my code.
> The big problem was that when doing log("String" + value + "message")
> is that the string concatenation is always done, regardless of whether
> the log level was enabled or not. That is why it was desirable to
> surround with the if() statements in the first place ...
Duh. We all agree on that. But when you have debug("my single string
message") there is not need to wrap, and when you do need the
isDebugEnabled() call, it will be very fast.
> So the problem is still going to exist, albeit a factor slower since
> it's going through this caching log :-/
Agree, that is what caching is all about.
-dain
Re: [Logs] Re: Logging code and Garbage Collection
Posted by Alex Blewitt <Al...@ioshq.com>.
I fear that this is a tad pointless; the logs in Log4J are going to do
this anyway, and not cache the log values.
The big problem was that when doing log("String" + value + "message")
is that the string concatenation is always done, regardless of whether
the log level was enabled or not. That is why it was desirable to
surround with the if() statements in the first place ...
So the problem is still going to exist, albeit a factor slower since
it's going through this caching log :-/
Alex.
On Thursday, Aug 14, 2003, at 23:02 Europe/London, Dain Sundstrom wrote:
> I have just checkin in a proof of concept CachingLog4jLog. This
> commons log implementation caches the values of the trace, debug, and
> info enabled flags. The flags are update on a periodic basis by a
> single java.util.Timer. The period is currently hard coded to 3
> minutes, but if people like this I can add a management interface to
> it.
>
> The warn, error and fatal levels are hard coded to true as log4j does
> not even expose a isXXXEnabled for these levels. The internal
> implementation of the trace, debug, and info methods do an explicit
> level check before delegating the the log4j logger. For example:
>
> public void info(Object message) {
> if (infoEnabled) {
> logger.log(FQCN, Priority.INFO, message, null);
> }
> }
>
>
> -dain
>
> On Thursday, August 14, 2003, at 03:14 AM, Alex Blewitt wrote:
>
>>
>> On Thursday, Aug 14, 2003, at 06:31 Europe/London, Pasi Salminen
>> wrote:
>>
>>> Putting my administrator hat on, I must say that I don't like
>>> application servers
>>> which do not enable change of logging level at runtime.
>>
>> Though personally I've not come across this before, I can see that it
>> would be a desirable thing to have.
>>
>>> Berin Loritsch wrote:
>>>
>>>> For example:
>>>>
>>>> if ( m_logger.isDebugEnabled() )
>>>> {
>>>> m_logger.debug( "test message" );
>>>> }
>>>>
>>>> is both slower and more cumbersome than this:
>>>>
>>>> m_logger.debug( "test message" );
>>
>> I will agree that there is more code. But bear in mind that w/o the
>> debugging guard, the m_logger.debug("message") will almost certainly
>> call m_logger.isDebugEnabled() (or access the boolean to do the test)
>> anyway, so in the (common) case when debugging isn't enabled then
>> IMHO it will make very little difference; possibly even run /faster/
>> with the guard.
>>
>> Bear in mind that 'is slower' and 'is faster' are only likely to be
>> based on what we humans think; until you've actually got code that is
>> running, and it is demonstrable that this is where the bottleneck is,
>> then pre-optimisation isn't worthwhile.
>>
>> Alex.
>>
>>
>
> /*************************
> * Dain Sundstrom
> * Partner
> * Core Developers Network
> *************************/
>
Re: [Logs] Re: Logging code and Garbage Collection
Posted by Dain Sundstrom <da...@coredevelopers.net>.
I have just checkin in a proof of concept CachingLog4jLog. This
commons log implementation caches the values of the trace, debug, and
info enabled flags. The flags are update on a periodic basis by a
single java.util.Timer. The period is currently hard coded to 3
minutes, but if people like this I can add a management interface to it.
The warn, error and fatal levels are hard coded to true as log4j does
not even expose a isXXXEnabled for these levels. The internal
implementation of the trace, debug, and info methods do an explicit
level check before delegating the the log4j logger. For example:
public void info(Object message) {
if (infoEnabled) {
logger.log(FQCN, Priority.INFO, message, null);
}
}
-dain
On Thursday, August 14, 2003, at 03:14 AM, Alex Blewitt wrote:
>
> On Thursday, Aug 14, 2003, at 06:31 Europe/London, Pasi Salminen wrote:
>
>> Putting my administrator hat on, I must say that I don't like
>> application servers
>> which do not enable change of logging level at runtime.
>
> Though personally I've not come across this before, I can see that it
> would be a desirable thing to have.
>
>> Berin Loritsch wrote:
>>
>>> For example:
>>>
>>> if ( m_logger.isDebugEnabled() )
>>> {
>>> m_logger.debug( "test message" );
>>> }
>>>
>>> is both slower and more cumbersome than this:
>>>
>>> m_logger.debug( "test message" );
>
> I will agree that there is more code. But bear in mind that w/o the
> debugging guard, the m_logger.debug("message") will almost certainly
> call m_logger.isDebugEnabled() (or access the boolean to do the test)
> anyway, so in the (common) case when debugging isn't enabled then IMHO
> it will make very little difference; possibly even run /faster/ with
> the guard.
>
> Bear in mind that 'is slower' and 'is faster' are only likely to be
> based on what we humans think; until you've actually got code that is
> running, and it is demonstrable that this is where the bottleneck is,
> then pre-optimisation isn't worthwhile.
>
> Alex.
>
>
/*************************
* Dain Sundstrom
* Partner
* Core Developers Network
*************************/