logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Elijah Baley" <e_ba...@hotmail.com>
Subject Re: Possible deadlock using AsyncAppender
Date Sun, 12 Feb 2006 09:08:45 GMT
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" <Tom.Drake@tavant.com>
To: "'Log4J Users List'" <log4j-user@logging.apache.org>
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:ttm@online.no]
> Sent: Friday, February 10, 2006 4:51 AM
> To: log4j-user@logging.apache.org
> 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 org.apache.log4j.helpers.BoundedFIFO@14471a3
> 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 org.apache.log4j.spi.RootLogger@320936 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 org.apache.log4j.spi.RootLogger@320936 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 org.apache.log4j.spi.RootLogger@320936 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: 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
>
> 

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org


Mime
View raw message