lock contention and scalability with the JDBC appender

Wed, 10 Aug 2005 07:19:24 -0700

We have hit a problem with log4j 1.29 this is causing the lock contention and as a result of this the CPU does not load. This stops the application scaling.
We are using a JDBC appender for application auditing and are dumping to a database certain request elements. The set up is 

client -> async appender --> jdbc appender

We have lots of threads waiting for a lock:


"ExecuteThread: '23' for queue: 'weblogic.kernel.Default'" daemon prio=5 
tid=0x0082a510 nid=0x26 waiting for monitor entry [89bfe000..89bffc28]

       at org.apache.log4j.Category.callAppenders(Category.java:186)
       - waiting to lock <0x9e4d9090> (a org.apache.log4j.Logger)
       at org.apache.log4j.Category.forcedLog(Category.java:372)
       at org.apache.log4j.Category.log(Category.java:864)
       at uk.zoop.core.logging.Logger.writeLog(Unknown Source)
       at uk.zoop.si.SILoggingUtils.logAuditInfo(Unknown Source)
       at uk.zoop.si.chain.Audit.execute(Unknown Source)

       at 
org.apache.commons.chain.impl.ChainBase.execute(ChainBase.java:166)

       at uk.zoop.si.chain.Head.execute(Unknown Source)

       at uk.zoop.si.listeners.http.HTTPSILChainServlet.doService(Unknown 
Source)
       at uk.zoop.si.listeners.http.HTTPSILChainServlet.doPost(Unknown 
Source)

       at javax.servlet.http.HttpServlet.service(HttpServlet.java:760)
       at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)

       at 
weblogic.servlet.internal.ServletStubImpl$ServletInvocationAction.run(ServletStubImpl.java:1006)
       at 
weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:419)
       at 
weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:315)
       at 
weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:6718)
       at 
weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)
       at 
weblogic.security.service.SecurityManager.runAs(SecurityManager.java:121)
       at 
weblogic.servlet.internal.WebAppServletContext.invokeServlet(WebAppServletContext.java:3764)
       at 
weblogic.servlet.internal.ServletRequestImpl.execute(ServletRequestImpl.java:2644)

       at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:219)
       at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:178)
This lock is held by:

"ExecuteThread: '18' for queue: 'weblogic.kernel.Default'" daemon prio=5 
tid=0x00e42ca0 nid=0x21 in Object.wait() [8a0fe000..8a0ffc28]

       at java.lang.Object.wait(Native Method)
       - waiting on <0x9e4d0620> (a org.apache.log4j.helpers.BoundedFIFO)
       at java.lang.Object.wait(Object.java:429)
       at org.apache.log4j.AsyncAppender.append(AsyncAppender.java:85)
       - locked <0x9e4d0620> (a org.apache.log4j.helpers.BoundedFIFO)

       at 
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)

       - locked <0x9e5739a0> (a org.apache.log4j.AsyncAppender)

       at 
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)

       at org.apache.log4j.Category.callAppenders(Category.java:187)
       - locked <0x9e4d9090> (a org.apache.log4j.Logger)
       at org.apache.log4j.Category.forcedLog(Category.java:372)
       at org.apache.log4j.Category.log(Category.java:864)
       at uk.zoop.core.logging.Logger.writeLog(Unknown Source)
       at uk.zoop.si.SILoggingUtils.logAuditInfo(Unknown Source)
       at uk.zoop.si.chain.Audit.execute(Unknown Source)

       at 
org.apache.commons.chain.impl.ChainBase.execute(ChainBase.java:166)

       at uk.zoop.si.chain.Head.execute(Unknown Source)

       at uk.zoop.si.listeners.http.HTTPSILChainServlet.doService(Unknown 
Source)
       at uk.zoop.si.listeners.http.HTTPSILChainServlet.doPost(Unknown 
Source)

       at javax.servlet.http.HttpServlet.service(HttpServlet.java:760)
       at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)

       at 
weblogic.servlet.internal.ServletStubImpl$ServletInvocationAction.run(ServletStubImpl.java:1006)
       at 
weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:419)
       at 
weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:315)
       at 
weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:6718)
       at 
weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)
       at 
weblogic.security.service.SecurityManager.runAs(SecurityManager.java:121)
       at 
weblogic.servlet.internal.WebAppServletContext.invokeServlet(WebAppServletContext.java:3764)
       at 
weblogic.servlet.internal.ServletRequestImpl.execute(ServletRequestImpl.java:2644)

       at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:219)
       at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:178)


and this thread appears to be in an apparent deadlock. This sounds like the 
following problem:


http://issues.apache.org/bugzilla/show_bug.cgi?id=24159
http://www.jboss.org/index.html?module=bb&op=viewtopic&t=56740


Is this a common problem with log4j under high load and with a JDBC appender 
and are there any ways around this? I have been using log4j for sometime but 
never the JDBC appender. Thoughts are moving to 1.3 and adding the changes 
suggested in 24159.



Any other ideas are welcome as we may not be able to move to 1.3 due to BEA 
not supporting it?


TIA

John Dewsnip



---------------------------------------------------------------------
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]























					Reply via email to