Mailing-List: contact log4j-user-help@logging.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "Log4J Users List" <log4j-user@logging.apache.org>
Received-SPF: pass (asf.osuosl.org: domain of stauffer.james@gmail.com
 designates 64.233.184.202 as permitted sender)
DomainKey-Signature: a=rsa-sha1; q=dns; c=nofws;
        s=beta; d=gmail.com;
        h=received:message-id:date:from:to:subject:in-reply-to:mime-version:content-type:content-transfer-encoding:content-disposition:references;
        b=EUxT/zeNBczREU933OY+NmxFE3UZqEHFGslf/BDRtfLjAM6WovFhFULr+14+JT4qBuwBAdGGpvvBtfJQr49UxhqdqxcVhpCsQJX8SPb8QXkPMGJaDZAF5PlTLEcAWySFD5IggImUo7WRni49Vs7j13lN5Jh/mhlHkXYHEWJZFhk=
Message-ID: <c83e39890602100631x3f1004f0q2bc9cd3843bd8255@mail.gmail.com>
Date: Fri, 10 Feb 2006 08:31:55 -0600
From: James Stauffer <stauffer.james@gmail.com>
To: Log4J Users List <log4j-user@logging.apache.org>, ttm@online.no
Subject: Re: Possible deadlock using AsyncAppender
In-Reply-To: <FOEHAMMERTTmC1B8hYz000000a1@nixon>
MIME-Version: 1.0
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: quoted-printable
Content-Disposition: inline
References: <FOEHAMMERTTmC1B8hYz000000a1@nixon>

When the buffer in AsyncAppender fills up, it will cause the current
thread to hand until it can remove something from the buffer.  If that
is what is happening and that isn't acceptable then AsyncAppender
isn't going to work for your product.

Besides that I have seen emails on this list related to other causes
of hanging but I don't know the details on that.

On 2/10/06, Thomas Muller <ttm@online.no> wrote:
> Log4j experts,
>
> We're using Log4j (version 1.2.9) extensibly in a high-performancy teleph=
ony
> 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 o=
f
> 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 oth=
er
> 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(App=
end
> 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(LDAP=
Pre
> 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(DailyRollingFileAppend=
er.
> java:313)
> org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppen=
der
> .java:343)
> org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
> org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
> org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(App=
end
> 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(SingleConnectionTCPSer=
ver
> .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(T=
icC
> 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 w=
ell
> 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-fil=
es,
> 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
>
>


--
James Stauffer
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