You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by Elias Ross <er...@m-qube.com> on 2003/10/24 23:17:42 UTC
Interesting deadlock situations - org.apache.log4j.spi.RootCategory
I just came across a deadlock condition in my code brought out by
Log4J. Here is a simplified view of the objects in play:
class State {
Logger log1;
synchronized void setState() {
// Something takes a long time here
log.debug("hello world");
}
synchronized Object getState() {
}
public String toString() {
return "state=" + getState();
}
}
So, imagine that I call in thread (1)
Logger log2;
State s = new State();
log.debug(s);
And then, in another thread (2), I called setState(). It is in the
middle of setState when this debug statement is fired.
In thread (1), the logger holds a lock on
'org.apache.log4j.spi.RootCategory'. The renderer attempts construct
the message by calling s.toString(), and toString calls getState().
Thread (1) has to wait for setState in thread (2) to exit. But setState
can't exit until it has finished logging.
So, I am wondering why can't the rendered render without holding the
lock on 'org.apache.log4j.spi.RootCategory'?
(An obvious fix is to not lock the getState routine.)
Maybe the moral of the story is don't have your debug statements hold
locks on your objects.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: log4j-user-help@jakarta.apache.org
Re: Interesting deadlock situations -
org.apache.log4j.spi.RootCategory
Posted by Elias Ross <er...@m-qube.com>.
Okay, let me finish, I'm sorry I hit send early by mistake. :-)
On Fri, 2003-10-24 at 15:26, Elias Ross wrote:
>
> Here is the stack trace:
org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
- locked <d6655dd0> (a
org.jboss.logging.appender.DailyRollingFileAppender)
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
org.apache.log4j.Category.callAppenders(Category.java:187)
- locked <d52e5db0> (a org.apache.log4j.spi.RootCategory)
I suggest what needs to happen is that the rendering stage has to take
place without holding any locks. But that would mean that
AppenderSkeleton would have to be re-written (but only slightly):
1. Holding locks, all major pre-conditions are checked. (Is the event
filterable? Is the threshold set too low?)
2. The message is rendered.
3. Holding any final locks necessary to actually write/output the
message, the rendered message is then sent to disk/the network/wherever.
I've run into this problem two times: One time while using JBoss,
another time using a third-party library that uses log4j. Since more
and more libraries and platforms use log4j (or commons-logging), this
sort of "rendering-interference"--especially on multiple-CPU
machines--is very worrisome.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: log4j-user-help@jakarta.apache.org
Re: Interesting deadlock situations -
org.apache.log4j.spi.RootCategory
Posted by Elias Ross <er...@m-qube.com>.
On Fri, 2003-10-24 at 14:17, Elias Ross wrote:
[cut]
> So, I am wondering why can't the rendered render without holding the
> lock on 'org.apache.log4j.spi.RootCategory'?
I'm replying to myself, I know...
Another work-around for this sort of deadlock would be for me write,
instead of log.debug(s), this sort of statement:
if (log.isDebugEnabled())
log.debug(s.toString());
That led me to wonder why any locks would have to be held at all while
'rendering' the object "s"...
Looking at the code in 1.2.8, there are two locks being held. One is in
Category.callAppenders. Right away, I realized there is another
(better) way to write this routine without holding any locks...
[before]
for(Category c = this; c != null; c=c.parent) {
// Protected against simultaneous call to addAppender,
removeAppender,...
synchronized(c) {
if(c.aai != null) {
writes += c.aai.appendLoopOnAppenders(event);
}
if(!c.additive) {
break;
}
}
}
[after]
for(Category c = this; c != null; c=c.parent) {
// Protected against simultaneous call to addAppender,
removeAppender,...
AppenderAttachableImpl aai = c.aai;
if (aai != null) {
writes += aai.appendLoopOnAppenders(event);
}
if(!c.additive) {
break;
}
}
The second lock comes from AppenderSkeleton:
public
synchronized
void doAppend(LoggingEvent event) {
if(closed) {
LogLog.error("Attempted to append to closed appender named
["+name+"].");
return;
}
Here is the stack trace:
This cannot be removed without affecting established
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: log4j-user-help@jakarta.apache.org
Re: Interesting deadlock situations -
org.apache.log4j.spi.RootCategory
Posted by Ceki Gülcü <ce...@qos.ch>.
This issue did never came up until a few days ago. I had a long discussion
with Erik Meade on irc on quite a similar problem.
(irc://irc.freenode.org:6667 on channel #apache-log4j)
At 02:17 PM 10/24/2003 -0700, Elias Ross wrote:
>I just came across a deadlock condition in my code brought out by
>Log4J. Here is a simplified view of the objects in play:
>
>class State {
> Logger log1;
>
> synchronized void setState() {
> // Something takes a long time here
> log.debug("hello world");
> }
>
> synchronized Object getState() {
> }
>
> public String toString() {
> return "state=" + getState();
> }
>}
>
>So, imagine that I call in thread (1)
>
>Logger log2;
>State s = new State();
>log.debug(s);
>
>And then, in another thread (2), I called setState(). It is in the
>middle of setState when this debug statement is fired.
>
>In thread (1), the logger holds a lock on
>'org.apache.log4j.spi.RootCategory'. The renderer attempts construct
>the message by calling s.toString(), and toString calls getState().
>
>Thread (1) has to wait for setState in thread (2) to exit. But setState
>can't exit until it has finished logging.
>
>So, I am wondering why can't the rendered render without holding the
>lock on 'org.apache.log4j.spi.RootCategory'?
>
>(An obvious fix is to not lock the getState routine.)
>
>
>Maybe the moral of the story is don't have your debug statements hold
>locks on your objects.
>
>
>
>---------------------------------------------------------------------
>To unsubscribe, e-mail: log4j-user-unsubscribe@jakarta.apache.org
>For additional commands, e-mail: log4j-user-help@jakarta.apache.org
--
Ceki Gülcü
For log4j documentation consider "The complete log4j manual"
ISBN: 2970036908 http://www.qos.ch/shop/products/clm_t.jsp
import org.apache.Facetime;
ApacheCon US 2003, 18-21 November http://apachecon.com/
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: log4j-user-help@jakarta.apache.org