Return-Path: Delivered-To: apmail-logging-log4j-user-archive@www.apache.org Received: (qmail 94488 invoked from network); 10 Feb 2006 12:51:52 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (209.237.227.199) by minotaur.apache.org with SMTP; 10 Feb 2006 12:51:52 -0000 Received: (qmail 40478 invoked by uid 500); 10 Feb 2006 12:51:48 -0000 Delivered-To: apmail-logging-log4j-user-archive@logging.apache.org Received: (qmail 40444 invoked by uid 500); 10 Feb 2006 12:51:48 -0000 Mailing-List: contact log4j-user-help@logging.apache.org; run by ezmlm Precedence: bulk List-Unsubscribe: List-Help: List-Post: List-Id: "Log4J Users List" Reply-To: "Log4J Users List" Delivered-To: mailing list log4j-user@logging.apache.org Received: (qmail 40433 invoked by uid 99); 10 Feb 2006 12:51:48 -0000 Received: from asf.osuosl.org (HELO asf.osuosl.org) (140.211.166.49) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 10 Feb 2006 04:51:48 -0800 X-ASF-Spam-Status: No, hits=0.0 required=10.0 tests= X-Spam-Check-By: apache.org Received-SPF: neutral (asf.osuosl.org: local policy) Received: from [193.116.28.10] (HELO nixon) (193.116.28.10) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 10 Feb 2006 04:51:47 -0800 Received: from satan ([10.0.2.26]) by nixon with Microsoft SMTPSVC(5.0.2195.6713); Fri, 10 Feb 2006 12:51:23 +0000 Reply-To: From: "Thomas Muller" To: Subject: Possible deadlock using AsyncAppender Date: Fri, 10 Feb 2006 12:51:24 -0000 MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit X-Mailer: Microsoft Office Outlook, Build 11.0.6353 X-MimeOLE: Produced By Microsoft MimeOLE V6.00.2900.2180 Thread-Index: AcYuQLJad++zNPCVR/mqKWR/uf2u1g== Message-ID: X-OriginalArrivalTime: 10 Feb 2006 12:51:23.0285 (UTC) FILETIME=[B26C1450:01C62E40] X-Virus-Checked: Checked by ClamAV on apache.org X-Spam-Rating: minotaur.apache.org 1.6.2 0/1000/N 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