Multithreading issues - doAppend is synchronised?

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

Multithreading issues - doAppend is synchronised?

paul womack
I've been using Log4j succesfully for around 4 years now,
but I think I've recently hit a limitation.

I currently have multiple "leaf" loggers connected to multiple appenders,
using additivity=false.

The appenders are all RollingFileAppenders.

This works fine.

I also have an "ErrorAppender". This is also a RollingFileAppender,
but the layout is a good deal more detailed. It also has a threashold
of "ERROR".

Each "leaf" logger is also connected to the ErrorAppender.

The upshot of all this is that each logger sends debug()
info() and warn() logging to its (1:1) Appender (AKA log file),
but any errors are logged both to the loggers "own" appender,
and to the ERROR appender, with much more information.

This all works nicely.

The practical upshot is, when something goes wrong,
I look in the error log file first.

But I'm having a performance issue. All this is used
under a heavily multi-thread tomcat context.

Given that doAppend in AppenderSkeleton is synchronized
to the Appender instance, and that the threshold is checked
inside doAppend, it appears to me (I'm about to try to confirm)
that every single log() call will synchronise on
the ErrorAppender instance, even if the logging is at the lowest
level.

The practical upshot is that every single log call becomes
a sync() on a global object.

That can't be good.

Is this a known issue, or is my analysis all wet?

Frankly, I'd be happy to be wrong on this one.

   BugBear

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Multithreading issues - doAppend is synchronised?

carnold-3

On Nov 3, 2009, at 6:13 AM, paul womack wrote:

> I've been using Log4j succesfully for around 4 years now,
> but I think I've recently hit a limitation.
>
> I currently have multiple "leaf" loggers connected to multiple  
> appenders,
> using additivity=false.
>
> The appenders are all RollingFileAppenders.
>
> This works fine.
>
> I also have an "ErrorAppender". This is also a RollingFileAppender,
> but the layout is a good deal more detailed. It also has a threashold
> of "ERROR".
>
> Each "leaf" logger is also connected to the ErrorAppender.
>
> The upshot of all this is that each logger sends debug()
> info() and warn() logging to its (1:1) Appender (AKA log file),
> but any errors are logged both to the loggers "own" appender,
> and to the ERROR appender, with much more information.
>
> This all works nicely.
>
> The practical upshot is, when something goes wrong,
> I look in the error log file first.
>
> But I'm having a performance issue. All this is used
> under a heavily multi-thread tomcat context.
>
> Given that doAppend in AppenderSkeleton is synchronized
> to the Appender instance, and that the threshold is checked
> inside doAppend, it appears to me (I'm about to try to confirm)
> that every single log() call will synchronise on
> the ErrorAppender instance, even if the logging is at the lowest
> level.
>
> The practical upshot is that every single log call becomes
> a sync() on a global object.
>
> That can't be good.
>
> Is this a known issue, or is my analysis all wet?
>
> Frankly, I'd be happy to be wrong on this one.
>
>  BugBear


Unfortunately, log4j 1.2 was designed in a era where concurrency was  
not as significant a concern.  Only one logging request can be in the  
pipeline after a logging request passes the initial threshold tests  
and is ready for dispatching to appenders.   The impact can be  
minimized by using AsyncAppender's to minimize the time spent in the  
synchronized block.

There has been a desire, but no active development, for a log4j 2.0  
that was designed for concurrency, JDK 5 and the all good things while  
having a simple migration path for log4j 1.2 users.  However, there  
has never been the critical mass of developers ready at the same time  
to make a go at it.

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Multithreading issues - doAppend is synchronised?

Pat Farrell
Curt Arnold wrote:
> Unfortunately, log4j 1.2 was designed in a era where concurrency was not
> as significant a concern.

As was typical of Java at the time.

The times have changed.

> There has been a desire, but no active development, for a log4j 2.0 that
> was designed for concurrency, JDK 5 and the all good things while having
> a simple migration path for log4j 1.2 users.  However, there has never
> been the critical mass of developers ready at the same time to make a go
> at it.

How far did this effort go? How close are/were you to the critical mass.
I'm very interested in this, and if its close, might be able to help.

--
Pat Farrell
http://www.pfarrell.com/


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Multithreading issues - doAppend is synchronised?

carnold-3

On Nov 8, 2009, at 2:18 PM, Pat Farrell wrote:

> Curt Arnold wrote:
>> Unfortunately, log4j 1.2 was designed in a era where concurrency  
>> was not
>> as significant a concern.
>
> As was typical of Java at the time.
>
> The times have changed.
>
>> There has been a desire, but no active development, for a log4j 2.0  
>> that
>> was designed for concurrency, JDK 5 and the all good things while  
>> having
>> a simple migration path for log4j 1.2 users.  However, there has  
>> never
>> been the critical mass of developers ready at the same time to make  
>> a go
>> at it.
>
> How far did this effort go? How close are/were you to the critical  
> mass.
> I'm very interested in this, and if its close, might be able to help.
>
> --
> Pat Farrell
> http://www.pfarrell.com/

There is a bug repo for log4j 2.0 that collects design goals, wish  
lists, ideas for log4j 2.0 at https://issues.apache.org/jira/browse/LOG4J2

Code-wise, I did some exploratory stuff several years ago around the  
back-end classes at http://svn.apache.org/repos/asf/logging/sandbox/experimental/pattern-layout 
.  The big ideas were to have an extract phase that collected  
invariant values from the logging context (that much had to be  
synchronized) and logging call and then everything else worked off the  
collected values and that the same back-end classes (appenders,  
layout, etc) should be independent from the logging API  
(java.util.logging, org.apache.log4j, etc).

Community wise, about a year ago we added an authorization class for  
log4j 2.0 development (no rights on 1.2 code base) and granted it to  
an existing ASF committer (Ralph Goers) who was interested in pitching  
in.

There is a bit of a chicken and egg syndrome at work.  I didn't  
proceed to flesh out a log4j 2.0 framework back in the day since  
without a community to review as it was being developed, it would be  
just one guys take on the problem.  However without at least a  
skeletal code base, it is hard for somebody to jump in and help out.

The mailing list archive has a lot of discussion on what log4j 2.0  
should look like if you up for mailing list archaeology.


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]