Re: Interesting deadlock situations - org.apache.log4j.spi.RootCategory

[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

[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