We adopted another approach to this problem in our project (which works for
US...) - we wrote a derived class (e.g., MyAsyncAppender) that checks the
current size of the bounded FIFO, and if that size is >= 95% (example) it
drops the log message and inserts a special "Some messages lost before..."
message. (Note: if size is >= 99% (example) then no such message is
droped)...
----- Original Message -----
From: "Tom Drake" <[EMAIL PROTECTED]>
To: "'Log4J Users List'" <[email protected]>
Sent: Saturday, February 11, 2006 00:59
Subject: RE: Possible deadlock using AsyncAppender
You should be aware that AsyncAppender is backed by a bounded fifo. When
this fifo gets full, all requests to that instance of the async appender
will block, until such time that fifo is no longer full. A 'background'
thread is used to consume the entries in the fifo.
So, if the subordinate appender is so slow that your async appender fifo
fills up, your application will appear to hang as soon as a logging call
is
made (which points to that appender).
If you can determine the maximum amount of time it takes to consume an
entry
in the fifo, the maximum sustained rate and time period at which entries
are
added to the fifo, then you can determine how large your fifo must be to
keep from filling up.
Tom
-----Original Message-----
From: Thomas Muller [mailto:[EMAIL PROTECTED]
Sent: Friday, February 10, 2006 4:51 AM
To: [email protected]
Subject: Possible deadlock using AsyncAppender
Log4j experts,
We're using Log4j (version 1.2.9) extensibly in a high-performancy
telephony
server, and in our latest release we have seen quite a few "frozen server"
incidents, i.e. extensive deadlocks significantly deteriorating service.
I've now managed to isolate the deadlocks (using Jconsole), and it seems
like /maybe/ log4j's AsyncAppender is the culprit. We're using a number of
AsyncAppenders for performance reasons.
Environment:
Log4j version: 1.2.9
Java version: 1.5.0 update 6
OS: Win32
This following shows a thread in WAITING state and there are a number
other
threads waiting for it (seemingly forever).
Name: Timer-0
State: WAITING on [EMAIL PROTECTED]
Total blocked: 9 Total waited: 7,025
Stack trace:
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:474)
org.apache.log4j.AsyncAppender.append(AsyncAppender.java:85)
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(Append
erAttachableImpl.java:57)
org.apache.log4j.Category.callAppenders(Category.java:194)
org.apache.log4j.Category.forcedLog(Category.java:379)
org.apache.log4j.Category.debug(Category.java:248)
com.onrelay.pref.ldap.LDAPPreferences.createPreferenceFromAttributes(LDAPPre
ferences.java:961)
[clip]
A thread waiting for Timer-0:
Name: Dispatcher-Thread-10
State: BLOCKED on [EMAIL PROTECTED] owned by: Timer-0
Total blocked: 5 Total waited: 12,707
Stack trace:
org.apache.log4j.Category.callAppenders(Category.java:192)
org.apache.log4j.Category.forcedLog(Category.java:379)
org.apache.log4j.Category.log(Category.java:826)
com.onrelay.log.LoggingOutputStream.flush(LoggingOutputStream.java:194)
java.io.PrintStream.write(PrintStream.java:414)
sun.nio.cs.StreamEncoder$CharsetSE.writeBytes(StreamEncoder.java:336)
sun.nio.cs.StreamEncoder$CharsetSE.implFlushBuffer(StreamEncoder.java:404)
sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:115)
java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:169)
java.io.PrintStream.write(PrintStream.java:459)
java.io.PrintStream.print(PrintStream.java:602)
java.io.PrintStream.println(PrintStream.java:739)
org.apache.log4j.helpers.LogLog.debug(LogLog.java:91)
org.apache.log4j.DailyRollingFileAppender.rollOver(DailyRollingFileAppender.
java:313)
org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender
.java:343)
org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(Append
erAttachableImpl.java:57)
org.apache.log4j.Dispatcher.run(AsyncAppender.java:310)
Yet another:
Name: SingleConnectionTCPServer-0
State: BLOCKED on [EMAIL PROTECTED] owned by: Timer-0
Total blocked: 1 Total waited: 0
Stack trace:
org.apache.log4j.Category.callAppenders(Category.java:192)
org.apache.log4j.Category.forcedLog(Category.java:379)
org.apache.log4j.Category.log(Category.java:844)
com.onrelay.log.LoggingElement.log(LoggingElement.java:183)
com.onrelay.log.LoggingElement.info(LoggingElement.java:90)
com.onrelay.server.SingleConnectionTCPServer$1.run(SingleConnectionTCPServer
.java:69)
java.lang.Thread.run(Thread.java:595)
Yet another:
Name: Timer-4
State: BLOCKED on [EMAIL PROTECTED] owned by: Timer-0
Total blocked: 5 Total waited: 1,595
Stack trace:
org.apache.log4j.Category.callAppenders(Category.java:192)
org.apache.log4j.Category.forcedLog(Category.java:379)
org.apache.log4j.Category.log(Category.java:844)
com.onrelay.log.LoggingElement.log(LoggingElement.java:183)
com.onrelay.log.LoggingElement.info(LoggingElement.java:90)
com.onrelay.mbx.protocol.AbstractSession.sessionIdle(AbstractSession.java:41
0)
com.onrelay.mbx.protocol.tic.socket.client.TicClientSession.sessionIdle(TicC
lientSession.java:233)
com.onrelay.mbx.protocol.AbstractSession$5.run(AbstractSession.java:620)
java.util.TimerThread.mainLoop(Timer.java:512)
java.util.TimerThread.run(Timer.java:462)
The list goes on - in this case there are 6 more threads hanging in log4j
statements with the same lines topping the stack:
org.apache.log4j.Category.callAppenders(Category.java:192)
org.apache.log4j.Category.forcedLog(Category.java:379)
FYI from the stack traces I can verify (I think) that we're talking about
different Loggers that have independent AsyncAppenders attached to them.
1. I'm I correct in believing this is caused by log4j code, or could it
well
be our own?
2. If 1 holds true, is this something someone can address, or am I on my
own
finding and fixing a possible flaw?
3. Does 1.2.13 have fix for this particular issue?
I can provide more information if needed, i.e. Log4j.xml file(s),
log-files,
code extracts etc.
Any input would be much appreciated.
--
Thomas
---------------------------------------------------------------------
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]
---------------------------------------------------------------------
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]
---------------------------------------------------------------------
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]
