You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by Elias Ross <er...@m-qube.com> on 2004/09/17 19:35:05 UTC
Improving Log4J concurrency, avoiding deadlock
I had a created a way to avoid a deadlock condition when Appender is
holding on to a lock and rendering an object. In some situations,
attempting to log during a toString() causes this. Refer to to Bugzilla
bug:
http://nagoya.apache.org/bugzilla/show_bug.cgi?id=24159
To understand why this is an issue, here are three statements:
1 Logger.debug(this);
2 Logger.debug(this.toString());
3 if (Logger.isDebugEnabled()) Logger.debug(this.toString());
1 - Does not call Object.toString until the last minute. This is good
because if debug is disabled, creates no overhead. Additionally, if the
Logger's threshold is DEBUG and no appender wants the event, then
creates no overload
2 - Creates overhead
3 - Creates no overhead if the logger threshold is above DEBUG
It is possible to call Format without locking the appender.
My proposed changes work (and probably would improve concurrency because
locking happens less often and during a Format) but I can understand
wanting to preserve compatibility so changing AppenderSkeleton might be
inappropriate. How about creating a AppenderSupport or AppenderBase?
It's also better design (IMHO) to factor canAppend into its own method.
Here are the overview changes:
* Add "protected boolean canAppend()" method. Subclasses override as
appropriate.
* Call canAppend before formatting (holding lock on "this")
* Format the message (no need to lock yet...)
* Synchronize on "this", check canAppend again. Log4J might just ignore
this step and try to log anyway. If there's an Exception (like the
writer was closed) then it's no big deal, Log4J just catches it and move
on.
* Call writer.write(String)
This is the subAppend from WriterAppender that does not lock:
protected void subAppend(LoggingEvent event) {
Layout l = this.layout;
if (l == null) {
errorHandler.error(
"No layout set for the appender named [" + name + "].");
return;
}
String fe = l.format(event);
String s[] = null;
if (l.ignoresThrowable()) {
s = event.getThrowableStrRep();
}
// Could be moved to its own synchronized method
synchronized (this) {
if (!canAppend(event)) return;
this.qw.write(fe);
if (s != null) {
int len = s.length;
for (int i = 0; i < len; i++) {
this.qw.write(s[i]);
this.qw.write(Layout.LINE_SEP);
}
}
if (this.immediateFlush) {
this.qw.flush();
}
}
}
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Improving Log4J concurrency, avoiding deadlock
Posted by Jacob Kjome <ho...@visi.com>.
At 04:08 PM 9/23/2004 -0700, you wrote:
>--- Elias Ross <er...@m-qube.com> wrote:
> > I feel a bit frustrated because I've been bitten in the ass a few
> > times encountering this "contrived" problem and I haven't been
> > taken very seriously pointing this out. As I have tried to explain,
> > this is something that has happened before on servers at this
> > company, and it's something we'd like to have fixed.
>
>Last time I checked log4j was open source.
Last time I checked, it seemed he realized this, so I'm not sure why you
see the need to point this out.
> Fix your version and be done
>with it. The official distribution will be "fixed" when an appropriate
>"fix" is determined. What is hard to understand about that?
He's taken the time to look at the source and provided the project with
patches that he finds reasonable and claims are backward compatible. He's
also trying to argue his case about why they should be included in the
Log4j distribution. Anyone working with open source understands that they
could fork the code and add whatever they want without it being accepted by
the project. There is an obvious reason to avoid this, however; extra
maintenance and having to keep the fork synchronized with continuing changes.
Bottom line: please don't discourage people who are actively contributing,
especially when you are making an irrelevant point obvious to anyone on
this list.
Jake
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Improving Log4J concurrency, avoiding deadlock
Posted by Niclas Hedhman <ni...@hedhman.org>.
On Sunday 26 September 2004 18:48, Ceki Gülcü wrote:
> In order to fix bug 24159, would it be possible for you to not log
> from within a synchronized resource which is also used from within
> rendering code?
May I quietly add, Mr Ross, that this is not at all unique to Log4J as a
subsystem, but to your entire application. Concurrency is a complex issue,
and one need to analyse the subsystems involved.
In my experience, one can assume that subsystems (not any class library) are
by default thread safe, and that means that they contain synchronization
internally, that you should know about.
What you do need to look at is "Are there any callbacks?"
Determining that can be trickier than one first imagine, for instance passing
an Object that will be called (for instance by the nasty and innocent
toString() ), then that is a kind of callback in this context.
If that exists, you need to be very careful about your own synchronization
schemes.
Thank you for your attention and patience if this seems overly basic to you.
Niclas
--
+------//-------------------+
/ http://www.bali.ac /
/ http://niclas.hedhman.org /
+------//-------------------+
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Improving Log4J concurrency, avoiding deadlock
Posted by Ceki Gülcü <ce...@qos.ch>.
At 09:39 PM 9/23/2004, Elias Ross wrote:
>On Thu, 2004-09-23 at 01:59, Ceki Gülcü wrote:
>
> > Some would say heavy-handed, others would say simple and robust. Given
> > the history of this discussion (see bug report 24159), I have a strong
> > bias against modifying the existing synchronization code in
> > AppenderSkeleton. The problem in 24159 is just too contrived to be
> > taken seriously.
>
>I feel a bit frustrated because I've been bitten in the ass a few times
>encountering this "contrived" problem and I haven't been taken very
>seriously pointing this out. As I have tried to explain, this is
>something that has happened before on servers at this company, and it's
>something we'd like to have fixed.
You are right to observe that bug 24159 has not been seriously. I am
sorry if you feel frustrated by the response to your inquiry. However,
I think bug 24159 can be fixed without modifying log4j code, as
described below.
In order to fix bug 24159, would it be possible for you to not log
from within a synchronized resource which is also used from within
rendering code? In your example, would it be possible for you not to
log from within the setState() method? The setState method is
synchronized on a resource, i.e. the State object instance, which is
also accessed in a synchronized manner from the toString()
method. This access pattern is the reason for the for the deadlock
you are observing. How difficult is it to avoid this pattern?
>I thought in the quest for helping fix this bug we could improve
>concurrency and multi-threading. Even if you think this bug is dumb,
>wouldn't you like to improve in this area?
I appreciate this discussion and especially your efforts in improving
concurrency in log4j code. However, since writing an event to disk or
any other device takes over 90% of the time required to complete a
logging operation, there is little to be gained in improving
concurrency outside those 90%. Note that this statement is true only
if the event is written to disk, if the event is disabled it is a
completely different ball game.
Now, bug 24159 occurs when the event is enabled, i.e. written to disk
or any other output device. Given the overwhelming weight of the code
for formatting and writing onto the output device (over 90% of cost),
I really don't think any noticeable performance gains could be
obtained by increasing concurrency in the code exercised by the
doAppend() method.
As far as I can tell, the only advantage obtained in changing the
concurrency model would be in avoiding the deadlock situations, e.g.
bug 24159. As mentioned earlier, bug 24159 could probably be solved
without modifying the existing log4j concurrently model.
>I sent out some changes that will maintain compatibility and fix this
>issue, have you seen them?\
Yes, I have. As you know, I have also spend considerable amount of time
understanding and testing bug 24159.
--
Ceki Gülcü
For log4j documentation consider "The complete log4j manual"
ISBN: 2970036908 http://www.qos.ch/shop/products/clm_t.jsp
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Improving Log4J concurrency, avoiding deadlock
Posted by Endre Stølsvik <En...@Stolsvik.com>.
On Thu, 23 Sep 2004 ectosphenoid-log4j@yahoo.com wrote:
| --- Elias Ross <er...@m-qube.com> wrote:
| > I feel a bit frustrated because I've been bitten in the ass a few
| > times encountering this "contrived" problem and I haven't been
| > taken very seriously pointing this out. As I have tried to explain,
| > this is something that has happened before on servers at this
| > company, and it's something we'd like to have fixed.
|
| Last time I checked log4j was open source. Fix your version and be done
| with it. The official distribution will be "fixed" when an appropriate
| "fix" is determined. What is hard to understand about that?
Ohmygod I find this attitude really really annoying.
What does it seem like this dude is doing, then? He's checking things out,
and trying to come into a dialogue with the developers, providing code and
-whatnot-.
Stop pointing those "you don't know Open Source"-fingers at people who
-obviously- know the game.
Endre
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Improving Log4J concurrency, avoiding deadlock
Posted by ec...@yahoo.com.
--- Elias Ross <er...@m-qube.com> wrote:
> I feel a bit frustrated because I've been bitten in the ass a few
> times encountering this "contrived" problem and I haven't been
> taken very seriously pointing this out. As I have tried to explain,
> this is something that has happened before on servers at this
> company, and it's something we'd like to have fixed.
Last time I checked log4j was open source. Fix your version and be done
with it. The official distribution will be "fixed" when an appropriate
"fix" is determined. What is hard to understand about that?
Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Improving Log4J concurrency, avoiding deadlock
Posted by Elias Ross <er...@m-qube.com>.
On Thu, 2004-09-23 at 01:59, Ceki Gülcü wrote:
> Some would say heavy-handed, others would say simple and robust. Given
> the history of this discussion (see bug report 24159), I have a strong
> bias against modifying the existing synchronization code in
> AppenderSkeleton. The problem in 24159 is just too contrived to be
> taken seriously.
I feel a bit frustrated because I've been bitten in the ass a few times
encountering this "contrived" problem and I haven't been taken very
seriously pointing this out. As I have tried to explain, this is
something that has happened before on servers at this company, and it's
something we'd like to have fixed.
If you one day turned on DEBUG and soon watched your server lock up,
you'd be shaking your fist at whoever designed log4j. It is not just
some annoying bug, it's also something that can result in your server
hanging. And I'd rather have the server reboot than do that... I admit
my test case was "contrived", but in the real world people employ
multiple levels of indirection and the actual triggering mechanism can
be quite convoluted. And it can lurk until one unlucky day somebody
unknowingly turns on DEBUG.
I thought in the quest for helping fix this bug we could improve
concurrency and multi-threading. Even if you think this bug is dumb,
wouldn't you like to improve in this area?
I sent out some changes that will maintain compatibility and fix this
issue, have you seen them?
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Improving Log4J concurrency, avoiding deadlock
Posted by Ceki Gülcü <ce...@qos.ch>.
At 10:23 PM 9/17/2004, Elias Ross wrote:
>The java.io.Writer classes are synchronized internally. There is a lock
>internally, so the only reason to lock externally is to synchronize
>state on another operation. Say, if you do w.write(X); w.write(Y);
Agreed.
If you look at the way Layouts are designed in 1.3, you should see
that layouts access the output stream directly. Thus, it is 100%
certain that the internal lock in java.io.Writer object is not
sufficient. The access pattern on the Writer, say w, will be
w.write(X1), w.write(X2), ..., w.write(Xn).
The fact that WriterAppender does not let it's layout write directly
to the underlying Writer is an commission. It will be corrected
shortly.
>If you want to write multiple times safely, you can lock the object
>directly. Holding a lock on the appender while doing all writes is a
>little heavy-handed.
Some would say heavy-handed, others would say simple and robust. Given
the history of this discussion (see bug report 24159), I have a strong
bias against modifying the existing synchronization code in
AppenderSkeleton. The problem in 24159 is just too contrived to be
taken seriously.
However, I really welcome this discussion because it raises
interesting questions, but please do not expect me or any other log4j
developer to casually adopt modifications which can have serious
impact. It is not going happen because someone thinks it's cool or
that it would solve some weird bug. It will happen only after we can
certain that the new code is correct, better, and easy to understand
and to maintain.
--
Ceki Gülcü
For log4j documentation consider "The complete log4j manual"
ISBN: 2970036908 http://www.qos.ch/shop/products/clm_t.jsp
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Improving Log4J concurrency, avoiding deadlock
Posted by Elias Ross <er...@m-qube.com>.
On Fri, 2004-09-17 at 11:51, Ceki Gülcü wrote:
> Do you realize that the main reason for synchronization in doAppend method
> is avoiding simultaneous writes to the same output device? Any write
> operation which is not synchronized (or otherwise protected against
> simultaneous access) is a big no no...
>
The java.io.Writer classes are synchronized internally. There is a lock
internally, so the only reason to lock externally is to synchronize
state on another operation. Say, if you do w.write(X); w.write(Y);
If you want to write multiple times safely, you can lock the object
directly. Holding a lock on the appender while doing all writes is a
little heavy-handed.
Yoav Shapira wrote:
> Hi,
> We also want to be careful not to change this central piece of code
> unless absolutely needed, i.e. if people start reporting bugs in this
> area. Log4j is in heavy use and this code has not significantly
> changed in years, so I'm inclined to think it's fairly solid ;)
I'm thinking log4j should keep what it has. I am just suggesting it
might be worthwhile having an implementation (or relative object tree)
of AppenderSkeleton which use, say read-write locks, that avoids this
problem.
I'd be happy to contribute this, so it'd be no work for the rest of you.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Improving Log4J concurrency, avoiding deadlock
Posted by Ceki Gülcü <ce...@qos.ch>.
Do you realize that the main reason for synchronization in doAppend method
is avoiding simultaneous writes to the same output device? Any write
operation which is not synchronized (or otherwise protected against
simultaneous access) is a big no no...
At 08:35 PM 9/17/2004, Elias Ross wrote:
>On Fri, 2004-09-17 at 10:40, Ceki Gülcü wrote:
> > Elias,
> >
> > How are your changes compatible with log4j 1.3 where layouts write
> directly
> > to the output stream without intermediary String objects?
>
>It would seem the same issue would occur if an appender is locked when a
>layout is writing directly to the output stream.
>
>Fundamentally, the changes would be the same.
>
>* Remove synchronization from AppenderSkeleton during doAppend
>(Possibly create a related class as the locking strategy is now
>different.)
>* subAppend would be changed as follows:
>
>src/java/org/apache/log4j/WriterAppender.java
>
> protected void subAppend(LoggingEvent event) {
> Layout l = this.layout;
> if (l == null) {
> errorHandler.error(
> "No layout set for the appender named [" + name + "].");
> return;
> }
> Writer w = this.qw;
> if (w == null)
> return;
> try {
> l.formatAndWriteEvent(w, event);
> if (this.immediateFlush) {
> this.qw.flush();
> }
> } catch (IOException e) {
> errorHandler.error("....")
> }
>
> }
>
>The only catch is if the threshold is being lowered when an event is
>going off. What will then happen is the event will be logged anyway.
>
>If the write is closed during the event, then potentially only half the
>stack trace will be logged if the writer is not locked.
>
>If this is a concern, you might want to create some sort of semaphore so
>that when an event is being logged, the appender state can't be
>affected. However, as many concurrent events can be logged at the same
>time.
>
>
>
>---------------------------------------------------------------------
>To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>For additional commands, e-mail: log4j-dev-help@logging.apache.org
--
Ceki Gülcü
For log4j documentation consider "The complete log4j manual"
ISBN: 2970036908 http://www.qos.ch/shop/products/clm_t.jsp
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Improving Log4J concurrency, avoiding deadlock
Posted by Elias Ross <er...@m-qube.com>.
On Fri, 2004-09-17 at 11:35, Elias Ross wrote:
> If this is a concern, you might want to create some sort of semaphore so
> that when an event is being logged, the appender state can't be
> affected. However, as many concurrent events can be logged at the same
> time.
>
Instead of a semaphore, what I really was thinking of was a read-write
lock. Somewhat paradoxically, the doAppend routine would hold a read
lock, and any attempt to modify the state of the logger would require a
write lock.
It seems like Log4J already has a cheap one that should do the job.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Improving Log4J concurrency, avoiding deadlock
Posted by Elias Ross <er...@m-qube.com>.
On Fri, 2004-09-17 at 10:40, Ceki Gülcü wrote:
> Elias,
>
> How are your changes compatible with log4j 1.3 where layouts write directly
> to the output stream without intermediary String objects?
It would seem the same issue would occur if an appender is locked when a
layout is writing directly to the output stream.
Fundamentally, the changes would be the same.
* Remove synchronization from AppenderSkeleton during doAppend
(Possibly create a related class as the locking strategy is now
different.)
* subAppend would be changed as follows:
src/java/org/apache/log4j/WriterAppender.java
protected void subAppend(LoggingEvent event) {
Layout l = this.layout;
if (l == null) {
errorHandler.error(
"No layout set for the appender named [" + name + "].");
return;
}
Writer w = this.qw;
if (w == null)
return;
try {
l.formatAndWriteEvent(w, event);
if (this.immediateFlush) {
this.qw.flush();
}
} catch (IOException e) {
errorHandler.error("....")
}
}
The only catch is if the threshold is being lowered when an event is
going off. What will then happen is the event will be logged anyway.
If the write is closed during the event, then potentially only half the
stack trace will be logged if the writer is not locked.
If this is a concern, you might want to create some sort of semaphore so
that when an event is being logged, the appender state can't be
affected. However, as many concurrent events can be logged at the same
time.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Improving Log4J concurrency, avoiding deadlock
Posted by Ceki Gülcü <ce...@qos.ch>.
Elias,
How are your changes compatible with log4j 1.3 where layouts write directly
to the output stream without intermediary String objects?
At 07:35 PM 9/17/2004, Elias Ross wrote:
>I had a created a way to avoid a deadlock condition when Appender is
>holding on to a lock and rendering an object. In some situations,
>attempting to log during a toString() causes this. Refer to to Bugzilla
>bug:
>
>http://nagoya.apache.org/bugzilla/show_bug.cgi?id=24159
>
>To understand why this is an issue, here are three statements:
>1 Logger.debug(this);
>2 Logger.debug(this.toString());
>3 if (Logger.isDebugEnabled()) Logger.debug(this.toString());
>
>1 - Does not call Object.toString until the last minute. This is good
>because if debug is disabled, creates no overhead. Additionally, if the
>Logger's threshold is DEBUG and no appender wants the event, then
>creates no overload
>2 - Creates overhead
>3 - Creates no overhead if the logger threshold is above DEBUG
>
>It is possible to call Format without locking the appender.
>
>My proposed changes work (and probably would improve concurrency because
>locking happens less often and during a Format) but I can understand
>wanting to preserve compatibility so changing AppenderSkeleton might be
>inappropriate. How about creating a AppenderSupport or AppenderBase?
>
>It's also better design (IMHO) to factor canAppend into its own method.
>
>Here are the overview changes:
>
>* Add "protected boolean canAppend()" method. Subclasses override as
>appropriate.
>* Call canAppend before formatting (holding lock on "this")
>* Format the message (no need to lock yet...)
>* Synchronize on "this", check canAppend again. Log4J might just ignore
>this step and try to log anyway. If there's an Exception (like the
>writer was closed) then it's no big deal, Log4J just catches it and move
>on.
>* Call writer.write(String)
>
>This is the subAppend from WriterAppender that does not lock:
>
> protected void subAppend(LoggingEvent event) {
> Layout l = this.layout;
> if (l == null) {
> errorHandler.error(
> "No layout set for the appender named [" + name + "].");
> return;
> }
> String fe = l.format(event);
> String s[] = null;
> if (l.ignoresThrowable()) {
> s = event.getThrowableStrRep();
> }
>
> // Could be moved to its own synchronized method
> synchronized (this) {
> if (!canAppend(event)) return;
> this.qw.write(fe);
> if (s != null) {
> int len = s.length;
> for (int i = 0; i < len; i++) {
> this.qw.write(s[i]);
> this.qw.write(Layout.LINE_SEP);
> }
> }
> if (this.immediateFlush) {
> this.qw.flush();
> }
> }
> }
--
Ceki Gülcü
For log4j documentation consider "The complete log4j manual"
ISBN: 2970036908 http://www.qos.ch/shop/products/clm_t.jsp
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org