You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by John Dewsnip <jo...@hotmail.com> on 2005/08/10 16:19:23 UTC

lock contention and scalability with the JDBC appender

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: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org

Re: lock contention and scalability with the JDBC appender

Posted by Jim Rice <ji...@gmail.com>.
John,

Just a quick thought. What about using a JMS Appender out of Log4J to an MDB 
to handle the JDBC communications?

Jim

On 8/10/05, John Dewsnip <jo...@hotmail.com> wrote:
> 
> 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: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
> 
>