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 "Iyer, Vidya" <iy...@amazon.com> on 2006/05/25 22:44:04 UTC
Log4j deadlock
Hi,
I'm running an application with several threads, and at the end of the program, each thread logs an info statement that it is shutting down. Unfortunately, I periodically see two threads get deadlocked with the below error. The docs say that log4j is supposed to be thread safe, but it looks like there might be a bug in the synchronized code. Has anyone experienced this before?
Found one Java-level deadlock:
=============================
"MessageReader-15":
waiting to lock monitor 0x0809f394 (object 0x666b4788, a java.io.PrintStream),
which is held by "main"
"main":
waiting to lock monitor 0x0809f494 (object 0x65e061a0, a org.apache.log4j.spi.RootLogger),
which is held by "MessageReader-15"
Thanks,
Vidya
Re: Log4j deadlock
Posted by "James A. N. Stauffer" <st...@gmail.com>.
The two threads use different loggers. If I made the sub-logger point
to the same appender with additivity=false would that prevent the
problem. It appears that Catagory.callAppenders locks each catagory
up the chain so setting additivity to false should prevent the two
threads from locking the same Catagory objects. Is that correct?
BTW, I am using 1.2.8.
On 9/24/07, James A. N. Stauffer <st...@gmail.com> wrote:
> Would reducing the number of logs that get to the appender reduce the
> chance for this? What else could be done to reduce the chance of it
> happening?
>
> On 9/21/07, Curt Arnold <ca...@apache.org> wrote:
> >
> > The most obvious way to get a deadlock where one of the monitors is
> > RootLogger or RootCategory would be when a log request is made
> > (possibly indirectly) in the course of processing a log request.
> >
>
> --
> James A. N. Stauffer http://www.geocities.com/stauffer_james/
> Are you good? Take the test at http://www.livingwaters.com/good/
>
--
James A. N. Stauffer http://www.geocities.com/stauffer_james/
Are you good? Take the test at http://www.livingwaters.com/good/
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Log4j deadlock
Posted by "James A. N. Stauffer" <st...@gmail.com>.
Would reducing the number of logs that get to the appender reduce the
chance for this? What else could be done to reduce the chance of it
happening?
On 9/21/07, Curt Arnold <ca...@apache.org> wrote:
>
> The most obvious way to get a deadlock where one of the monitors is
> RootLogger or RootCategory would be when a log request is made
> (possibly indirectly) in the course of processing a log request.
>
--
James A. N. Stauffer http://www.geocities.com/stauffer_james/
Are you good? Take the test at http://www.livingwaters.com/good/
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Log4j deadlock
Posted by Curt Arnold <ca...@apache.org>.
On Sep 24, 2007, at 11:59 AM, James A. N. Stauffer wrote:
> I used to have additivity set to false for sps.webec.sql (I don't know
> why it was changed). Would that be sufficient to fix it?
>
Don't know the rest of your configuration or the logger names in use,
so I can't say. Whatever you do needs to prevent logging requests
from within the ConnectionBroker code from being directly dispatched
to the sps....DBAppender. If the DBAppender is only attached at the
root, setting additivity to false will prevent the ConnectionBroker
requests from reaching the sps...DBAppender and would avoid the problem.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Log4j deadlock
Posted by "James A. N. Stauffer" <st...@gmail.com>.
I used to have additivity set to false for sps.webec.sql (I don't know
why it was changed). Would that be sufficient to fix it?
On 9/24/07, Curt Arnold <ca...@apache.org> wrote:
>
> On Sep 24, 2007, at 8:59 AM, James A. N. Stauffer wrote:
>
> > Does this provide any clues?
>
> Yes, the problem is shown in the stack trace.
> sps.webec.sql.ConnectionBroker uses log4j internally and is also used
> to implement an log4j appender. The problem comes that the order of
> obtaining locks is inconsistent. In the first thread it is:
>
> synchronized(ConnectionBroker) {
> synchronized(RootCategory) {
> append message;
> }
> }
>
> In the other thread it is:
>
> synchronized(RootCategory) {
> start DB appending
> synchronized(ConnectionBroker) {
> finish DB appending;
> }
> }
>
> The deadlock occurs when each thread gets its first lock, but can't
> get its second.
>
>
> > Do you have suggestions on what I should do?
> >
>
> If you are just using the sps.webec packages and have no ability to
> change the code, you could work around the problem by configuration
> changes so that the sps.webec.sql.ConnectionBroker logging requests
> aren't sent to a sps.webec.server.util.DBAppender (at least
> directly). If you know the logger names used in that code, you could
> set the threshold to OFF, you could direct the logging requests to a
> different type of appender (console or file). You could also wrap
> the sps.webec.server.util.DBAppender with an AsyncAppender with
> blocking = false.
>
> If you do have ability to change the code, then you could look at the
> possibility of moving the logging code in ConnectionBroker so that
> logging occurs after the ConnectionBroker lock is released.
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
--
James A. N. Stauffer http://www.geocities.com/stauffer_james/
Are you good? Take the test at http://www.livingwaters.com/good/
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Log4j deadlock
Posted by Curt Arnold <ca...@apache.org>.
On Sep 24, 2007, at 8:59 AM, James A. N. Stauffer wrote:
> Does this provide any clues?
Yes, the problem is shown in the stack trace.
sps.webec.sql.ConnectionBroker uses log4j internally and is also used
to implement an log4j appender. The problem comes that the order of
obtaining locks is inconsistent. In the first thread it is:
synchronized(ConnectionBroker) {
synchronized(RootCategory) {
append message;
}
}
In the other thread it is:
synchronized(RootCategory) {
start DB appending
synchronized(ConnectionBroker) {
finish DB appending;
}
}
The deadlock occurs when each thread gets its first lock, but can't
get its second.
> Do you have suggestions on what I should do?
>
If you are just using the sps.webec packages and have no ability to
change the code, you could work around the problem by configuration
changes so that the sps.webec.sql.ConnectionBroker logging requests
aren't sent to a sps.webec.server.util.DBAppender (at least
directly). If you know the logger names used in that code, you could
set the threshold to OFF, you could direct the logging requests to a
different type of appender (console or file). You could also wrap
the sps.webec.server.util.DBAppender with an AsyncAppender with
blocking = false.
If you do have ability to change the code, then you could look at the
possibility of moving the logging code in ConnectionBroker so that
logging occurs after the ConnectionBroker lock is released.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Log4j deadlock
Posted by "James A. N. Stauffer" <st...@gmail.com>.
Does this provide any clues? Do you have suggestions on what I should do?
Java stack information for the threads listed above:
===================================================
"ConnectorThread jdbc:weblogic:mssqlserver4:webformslogs@webarc1:1433":
at org.apache.log4j.Category.callAppenders(Category.java:185)
- waiting to lock <0xa63067d0> (a org.apache.log4j.spi.RootCategory)
at org.apache.log4j.Category.forcedLog(Category.java:372)
at org.apache.log4j.Category.info(Category.java:674)
at sps.webec.sql.ConnectionBroker.connect(ConnectionBroker.java:260)
at sps.webec.sql.ConnectionBroker.createFree(ConnectionBroker.java:232)
- locked <0xa6305750> (a sps.webec.sql.ConnectionBroker)
at sps.webec.sql.ConnectionBroker.access$200(ConnectionBroker.java:23)
at sps.webec.sql.ConnectionBroker$ConnectorThread.run(ConnectionBroker.java:346)
"main":
at sps.webec.sql.ConnectionBroker.getConnectionAttributes(ConnectionBroker.java:62)
- waiting to lock <0xa6305750> (a sps.webec.sql.ConnectionBroker)
at sps.webec.sql.DatabaseManager.getConnectionAttributes(DatabaseManager.java:490)
at sps.webec.sql.DatabaseManager.executeInsert(DatabaseManager.java:227)
at sps.webec.sql.DatabaseManager.execute(DatabaseManager.java:64)
at sps.webec.server.util.DBAppender.append(DBAppender.java:65)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
- locked <0xa618b640> (a sps.webec.server.util.DBAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
at org.apache.log4j.Category.callAppenders(Category.java:187)
- locked <0xa63067d0> (a org.apache.log4j.spi.RootCategory)
at org.apache.log4j.Category.forcedLog(Category.java:372)
at org.apache.log4j.Category.error(Category.java:303)
at sps.webec.server.util.Log.LogException(Log.java:124)
at sps.webec.engine.Logger.logException(Logger.java:155)
at sps.webec.engine.FEDSException.logException(FEDSException.java:197)
at sps.webec.engine.Engine.createExceptionLog(Engine.java:637)
at sps.webec.engine.Engine.handleFEDSException(Engine.java:679)
at sps.webec.engine.Engine.receive(Engine.java:990)
at sps.webec.engine.Engine.processReceive(Engine.java:409)
at sps.webec.engine.Engine.processArguments(Engine.java:247)
at sps.webec.engine.Engine.start(Engine.java:143)
at sps.webec.engine.Engine.main(Engine.java:76)
On 9/21/07, Curt Arnold <ca...@apache.org> wrote:
>
> On Sep 21, 2007, at 3:18 PM, James A. N. Stauffer wrote:
>
> > We don't redirect System.out or System.err. Both stack traces showed
> > that both threads were calling logger.debug or logger.info.
>
> Calling stacks would be very helpful to try to analyze the problem.
> The most obvious way to get a deadlock where one of the monitors is
> RootLogger or RootCategory would be when a log request is made
> (possibly indirectly) in the course of processing a log request.
>
> > On Sep 21, 2007, at 10:18 AM, James A. N. Stauffer wrote:
> >
> >
> >> After years of using log4j I also encountered this. Is it a freak,
> >> rare occurance or is there a cause that can be addressed?
>
> Finer grain and provably safe concurrency is the primary design
> objective for log4j 2.0 and can not be achieved without significant
> implementation and API changes (hence why it has to be part of log4j
> 2.0 and not a 1.x). The internals of log4j 1.x are not thread-safe
> but depend on coarse-grained locks to prevent more than more one log
> request to be processed at a time. The coarse grained locks
> significantly impact performance on multi-core machines and leave the
> potential for these types of deadlocks. Individual problems can be
> analyzed and fixed or worked around, but eliminating all potential
> problems requires a near complete rework.
>
>
>
>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
--
James A. N. Stauffer http://www.geocities.com/stauffer_james/
Are you good? Take the test at http://www.livingwaters.com/good/
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Log4j deadlock
Posted by Curt Arnold <ca...@apache.org>.
On Sep 21, 2007, at 3:18 PM, James A. N. Stauffer wrote:
> We don't redirect System.out or System.err. Both stack traces showed
> that both threads were calling logger.debug or logger.info.
Calling stacks would be very helpful to try to analyze the problem.
The most obvious way to get a deadlock where one of the monitors is
RootLogger or RootCategory would be when a log request is made
(possibly indirectly) in the course of processing a log request.
> On Sep 21, 2007, at 10:18 AM, James A. N. Stauffer wrote:
>
>
>> After years of using log4j I also encountered this. Is it a freak,
>> rare occurance or is there a cause that can be addressed?
Finer grain and provably safe concurrency is the primary design
objective for log4j 2.0 and can not be achieved without significant
implementation and API changes (hence why it has to be part of log4j
2.0 and not a 1.x). The internals of log4j 1.x are not thread-safe
but depend on coarse-grained locks to prevent more than more one log
request to be processed at a time. The coarse grained locks
significantly impact performance on multi-core machines and leave the
potential for these types of deadlocks. Individual problems can be
analyzed and fixed or worked around, but eliminating all potential
problems requires a near complete rework.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Log4j deadlock
Posted by "James A. N. Stauffer" <st...@gmail.com>.
We don't redirect System.out or System.err. Both stack traces showed
that both threads were calling logger.debug or logger.info.
On 9/21/07, Curt Arnold <ca...@apache.org> wrote:
> Took me a while to notice that the quoted post is over a year old. I
> didn't see any follow up in the archives. In the original posting,
> that it is a block between a lock on a PrintStream and a RootLogger
> suggest to me that System.out might have been redirected to log4j and
> when log4j attempted to write to LogLog, it blocked. But that is
> just a guess, however anything that redirects System.out or .err to
> log4j would be likely to encounter deadlocks.
>
>
> On Sep 21, 2007, at 10:18 AM, James A. N. Stauffer wrote:
>
> > After years of using log4j I also encountered this. Is it a freak,
> > rare occurance or is there a cause that can be addressed?
> >
> > Found one Java-level deadlock:
> > =============================
> > "ConnectorThread
> > jdbc:weblogic:mssqlserver4:webformslogs@webarc1:1433":
> > waiting to lock monitor 0x000e00d8 (object 0xa63067d0, a
> > org.apache.log4j.spi.RootCategory),
> > which is held by "main"
> > "main":
> > waiting to lock monitor 0x000e0120 (object 0xa6305750, a
> > sps.webec.sql.ConnectionBroker),
> > which is held by "ConnectorThread
> > jdbc:weblogic:mssqlserver4:webformslogs@webarc1:1433"
> >
> >
> > On 5/25/06, Iyer, Vidya <iy...@amazon.com> wrote:
> >> Hi,
> >>
> >> I'm running an application with several threads, and at the end of
> >> the program, each thread logs an info statement that it is
> >> shutting down. Unfortunately, I periodically see two threads get
> >> deadlocked with the below error. The docs say that log4j is
> >> supposed to be thread safe, but it looks like there might be a bug
> >> in the synchronized code. Has anyone experienced this before?
> >>
> >> Found one Java-level deadlock:
> >> =============================
> >> "MessageReader-15":
> >> waiting to lock monitor 0x0809f394 (object 0x666b4788, a
> >> java.io.PrintStream),
> >> which is held by "main"
> >> "main":
> >> waiting to lock monitor 0x0809f494 (object 0x65e061a0, a
> >> org.apache.log4j.spi.RootLogger),
> >> which is held by "MessageReader-15"
> >>
> >>
> >> Thanks,
> >> Vidya
> >>
> >>
> >
> >
> > --
> > James A. N. Stauffer http://www.geocities.com/stauffer_james/
> > Are you good? Take the test at http://www.livingwaters.com/good/
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> > For additional commands, e-mail: log4j-user-help@logging.apache.org
> >
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
--
James A. N. Stauffer http://www.geocities.com/stauffer_james/
Are you good? Take the test at http://www.livingwaters.com/good/
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Log4j deadlock
Posted by Curt Arnold <ca...@apache.org>.
Took me a while to notice that the quoted post is over a year old. I
didn't see any follow up in the archives. In the original posting,
that it is a block between a lock on a PrintStream and a RootLogger
suggest to me that System.out might have been redirected to log4j and
when log4j attempted to write to LogLog, it blocked. But that is
just a guess, however anything that redirects System.out or .err to
log4j would be likely to encounter deadlocks.
On Sep 21, 2007, at 10:18 AM, James A. N. Stauffer wrote:
> After years of using log4j I also encountered this. Is it a freak,
> rare occurance or is there a cause that can be addressed?
>
> Found one Java-level deadlock:
> =============================
> "ConnectorThread
> jdbc:weblogic:mssqlserver4:webformslogs@webarc1:1433":
> waiting to lock monitor 0x000e00d8 (object 0xa63067d0, a
> org.apache.log4j.spi.RootCategory),
> which is held by "main"
> "main":
> waiting to lock monitor 0x000e0120 (object 0xa6305750, a
> sps.webec.sql.ConnectionBroker),
> which is held by "ConnectorThread
> jdbc:weblogic:mssqlserver4:webformslogs@webarc1:1433"
>
>
> On 5/25/06, Iyer, Vidya <iy...@amazon.com> wrote:
>> Hi,
>>
>> I'm running an application with several threads, and at the end of
>> the program, each thread logs an info statement that it is
>> shutting down. Unfortunately, I periodically see two threads get
>> deadlocked with the below error. The docs say that log4j is
>> supposed to be thread safe, but it looks like there might be a bug
>> in the synchronized code. Has anyone experienced this before?
>>
>> Found one Java-level deadlock:
>> =============================
>> "MessageReader-15":
>> waiting to lock monitor 0x0809f394 (object 0x666b4788, a
>> java.io.PrintStream),
>> which is held by "main"
>> "main":
>> waiting to lock monitor 0x0809f494 (object 0x65e061a0, a
>> org.apache.log4j.spi.RootLogger),
>> which is held by "MessageReader-15"
>>
>>
>> Thanks,
>> Vidya
>>
>>
>
>
> --
> James A. N. Stauffer http://www.geocities.com/stauffer_james/
> Are you good? Take the test at http://www.livingwaters.com/good/
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Log4j deadlock
Posted by "James A. N. Stauffer" <st...@gmail.com>.
After years of using log4j I also encountered this. Is it a freak,
rare occurance or is there a cause that can be addressed?
Found one Java-level deadlock:
=============================
"ConnectorThread jdbc:weblogic:mssqlserver4:webformslogs@webarc1:1433":
waiting to lock monitor 0x000e00d8 (object 0xa63067d0, a
org.apache.log4j.spi.RootCategory),
which is held by "main"
"main":
waiting to lock monitor 0x000e0120 (object 0xa6305750, a
sps.webec.sql.ConnectionBroker),
which is held by "ConnectorThread
jdbc:weblogic:mssqlserver4:webformslogs@webarc1:1433"
On 5/25/06, Iyer, Vidya <iy...@amazon.com> wrote:
> Hi,
>
> I'm running an application with several threads, and at the end of the program, each thread logs an info statement that it is shutting down. Unfortunately, I periodically see two threads get deadlocked with the below error. The docs say that log4j is supposed to be thread safe, but it looks like there might be a bug in the synchronized code. Has anyone experienced this before?
>
> Found one Java-level deadlock:
> =============================
> "MessageReader-15":
> waiting to lock monitor 0x0809f394 (object 0x666b4788, a java.io.PrintStream),
> which is held by "main"
> "main":
> waiting to lock monitor 0x0809f494 (object 0x65e061a0, a org.apache.log4j.spi.RootLogger),
> which is held by "MessageReader-15"
>
>
> Thanks,
> Vidya
>
>
--
James A. N. Stauffer http://www.geocities.com/stauffer_james/
Are you good? Take the test at http://www.livingwaters.com/good/
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org