Uploaded image for project: 'Application Server 3 4 5 and 6'
  1. Application Server 3 4 5 and 6
  2. JBAS-2393

Deadlock in RepositoryClassLoader

    XMLWordPrintable

Details

    Description

      We have experienced a threading deadlock in our application server. Using kill -3 we have extracted the JVM stack dump and identified the threads that have locked. The lock is a combination of JBoss, Log4J and TopLink (oracle OR mapping tool). Because several software libraries are in play it is debatable which one is causing the problem. My interpretation is that the Log4J logging within the RepositoryClassLoader is the issue.

      The first thread is loading a resource bundle which results in aquiring the org.jboss.mx.loading.UnifiedClassLoader3 monitor lock and then attempting to acquire the org.apache.log4j.spi.RootCategory monitor lock to output a debug message.
      The second thread has encountered an exception and has already aquired the org.apache.log4j.spi.RootCategory monitor lock to record this. Unfortunately the exception class then tries to load a resource bundle to get an internationalised error message. This causes this thread to attempt acquisition of the org.jboss.mx.loading.UnifiedClassLoader3 monitor lock.

      I haven't yet had a chance to reproduce this 4.0.3 final but I have inspected the source code changes to the relevant classes and do not see anything in this release that would fix the problem. I am currently investigating some other workarounds.

      The stack trace from the first thread is given below:
      "JMS SessionPool Worker-64" daemon prio=1 tid=0x9079c388 nid=0x5cde waiting for monitor entry [961da000..961db878]
      at org.apache.log4j.Category.callAppenders(Category.java:185)

      • waiting to lock <0x4be5cf70> (a org.apache.log4j.spi.RootCategory)
        at org.apache.log4j.Category.forcedLog(Category.java:372)
        at org.apache.log4j.Category.log(Category.java:864)
        at org.jboss.logging.Log4jLoggerPlugin.debug(Log4jLoggerPlugin.java:128)
        at org.jboss.logging.Logger.debug(Logger.java:144)
        at org.jboss.mx.loading.RepositoryClassLoader.setRepository(RepositoryClassLoader.java:117)
        at org.jboss.mx.loading.UnifiedClassLoader3.<init>(UnifiedClassLoader3.java:65)
        at org.jboss.mx.loading.HeirarchicalLoaderRepository3$GetClassLoadersAction.run(HeirarchicalLoaderRepository3.java:525)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.jboss.mx.loading.HeirarchicalLoaderRepository3.getPackageClassLoaders(HeirarchicalLoaderRepository3.java:419)
        at org.jboss.mx.loading.LoadMgr3.beginLoadTask(LoadMgr3.java:164)
        at org.jboss.mx.loading.RepositoryClassLoader.loadClassImpl(RepositoryClassLoader.java:475)
      • locked <0x4dabac40> (a org.jboss.mx.loading.UnifiedClassLoader3)
        at org.jboss.mx.loading.RepositoryClassLoader.loadClass(RepositoryClassLoader.java:377)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:235)
        at java.util.ResourceBundle.loadBundle(ResourceBundle.java:1058)
        at java.util.ResourceBundle.findBundle(ResourceBundle.java:928)
        at java.util.ResourceBundle.getBundleImpl(ResourceBundle.java:765)
        at java.util.ResourceBundle.getBundle(ResourceBundle.java:579)
        at oracle.toplink.localization.ToplinkLocalization.buildMessage(ToplinkLocalization.java:35)
        at oracle.toplink.localization.LoggingLocalization.buildMessage(LoggingLocalization.java:16)
        at oracle.toplink.publicinterface.Session.logMessage(Session.java:2254)
        at oracle.toplink.internal.databaseaccess.ParameterizedSQLBatchWritingMechanism.executeBatchedStatements(ParameterizedSQLBatchWritingMechanism.java:118)
        at oracle.toplink.internal.databaseaccess.DatabaseAccessor.commitTransaction(DatabaseAccessor.java:348)
        at oracle.toplink.publicinterface.Session.basicCommitTransaction(Session.java:368)
        at oracle.toplink.threetier.ClientSession.basicCommitTransaction(ClientSession.java:113)
        at oracle.toplink.publicinterface.Session.commitTransaction(Session.java:537)
        at oracle.toplink.publicinterface.UnitOfWork.commitTransaction(UnitOfWork.java:1177)
        at oracle.toplink.publicinterface.UnitOfWork.commitToDatabase(UnitOfWork.java:1102)
        at oracle.toplink.publicinterface.UnitOfWork.commitToDatabaseWithChangeSet(UnitOfWork.java:1137)
        at oracle.toplink.publicinterface.UnitOfWork.issueSQLbeforeCompletion(UnitOfWork.java:2492)
        at oracle.toplink.jts.AbstractSynchronizationListener.beforeCompletion(AbstractSynchronizationListener.java:151)
        at org.jboss.tm.TransactionImpl.doBeforeCompletion(TransactionImpl.java:1473)
        at org.jboss.tm.TransactionImpl.beforePrepare(TransactionImpl.java:1092)
        at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:306)
        at org.jboss.ejb.plugins.TxInterceptorCMT.endTransaction(TxInterceptorCMT.java:486)
        at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:396)
        at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)
        at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:139)
        at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)
        at org.jboss.ejb.plugins.CleanShutdownInterceptor.invoke(CleanShutdownInterceptor.java:264)
        at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
        at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:624)
        at org.jboss.ejb.Container.invoke(Container.java:873)
        at org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invoke(BaseLocalProxyFactory.java:415)
        at org.jboss.ejb.plugins.local.StatelessSessionProxy.invoke(StatelessSessionProxy.java:88)
        at $Proxy555.logMessageReceiptInNewTransaction(Unknown Source)
        at uk.co.abacus.jabs.msg.auditlogging.AbstractDatabaseAuditor.logJMSMessageReceived(AbstractDatabaseAuditor.java:116)
        at uk.co.abacus.jabs.msg.jms.JABSProxyMDBean.onMessage(JABSProxyMDBean.java:93)
        at sun.reflect.GeneratedMethodAccessor141.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:324)
        at org.jboss.invocation.Invocation.performCall(Invocation.java:345)
        at org.jboss.ejb.MessageDrivenContainer$ContainerInterceptor.invoke(MessageDrivenContainer.java:475)
        at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:149)
        at org.jboss.ejb.plugins.MessageDrivenInstanceInterceptor.invoke(MessageDrivenInstanceInterceptor.java:101)
        at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:48)
        at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:105)
        at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:335)
        at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)
        at org.jboss.ejb.plugins.RunAsSecurityInterceptor.invoke(RunAsSecurityInterceptor.java:94)
        at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)
        at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
        at org.jboss.ejb.MessageDrivenContainer.internalInvoke(MessageDrivenContainer.java:389)
        at org.jboss.ejb.Container.invoke(Container.java:873)
        at org.jboss.ejb.plugins.jms.JMSContainerInvoker.invoke(JMSContainerInvoker.java:1077)
        at org.jboss.ejb.plugins.jms.JMSContainerInvoker$MessageListenerImpl.onMessage(JMSContainerInvoker.java:1379)
        at org.jboss.jms.asf.StdServerSession.onMessage(StdServerSession.java:256)
        at org.jboss.mq.SpyMessageConsumer.sessionConsumerProcessMessage(SpyMessageConsumer.java:904)
        at org.jboss.mq.SpyMessageConsumer.addMessage(SpyMessageConsumer.java:160)
        at org.jboss.mq.SpySession.run(SpySession.java:333)
      • locked <0x52d68fd8> (a java.util.LinkedList)
        at org.jboss.jms.asf.StdServerSession.run(StdServerSession.java:180)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:743)
        at java.lang.Thread.run(Thread.java:534)

      The stack trace for the second thread is given below:
      "JMS SessionPool Worker-47" daemon prio=1 tid=0x8f629c00 nid=0x5cde waiting for monitor entry [945a2000..945a3878]
      at org.jboss.mx.loading.RepositoryClassLoader.loadClassImpl(RepositoryClassLoader.java:426)

      • waiting to lock <0x4dabac40> (a org.jboss.mx.loading.UnifiedClassLoader3)
        at org.jboss.mx.loading.RepositoryClassLoader.loadClass(RepositoryClassLoader.java:377)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:235)
        at java.util.ResourceBundle.loadBundle(ResourceBundle.java:1058)
        at java.util.ResourceBundle.findBundle(ResourceBundle.java:928)
        at java.util.ResourceBundle.getBundleImpl(ResourceBundle.java:765)
        at java.util.ResourceBundle.getBundle(ResourceBundle.java:579)
        at oracle.toplink.exceptions.i18n.ExceptionMessageGenerator.getHeader(ExceptionMessageGenerator.java:58)
        at oracle.toplink.exceptions.TopLinkException.printStackTrace(TopLinkException.java:161)
        at org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:50)
        at org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:333)
        at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:295)
        at org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender.java:349)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
      • locked <0x4c143780> (a org.jboss.logging.appender.DailyRollingFileAppender)
        at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
        at org.apache.log4j.Category.callAppenders(Category.java:187)
      • locked <0x4be5cf70> (a org.apache.log4j.spi.RootCategory)
        at org.apache.log4j.Category.forcedLog(Category.java:372)
        at org.apache.log4j.Category.info(Category.java:691)
        at uk.co.abacus.jabs.toplink.TopLinkSessionLogger.log(TopLinkSessionLogger.java:35)
        at oracle.toplink.publicinterface.Session.log(Session.java:2132)
        at oracle.toplink.publicinterface.Session.logException(Session.java:2208)
        at oracle.toplink.publicinterface.Session.handleException(Session.java:1816)
        at oracle.toplink.publicinterface.Session.executeQuery(Session.java:1116)
        at oracle.toplink.publicinterface.Session.executeQuery(Session.java:1038)
        at oracle.toplink.publicinterface.Session.readObject(Session.java:2510)
        at uk.co.abacus.jabs.msg.ejb.MessageAuditRecordSBean.update(MessageAuditRecordSBean.java:196)
        at uk.co.abacus.jabs.msg.ejb.MessageAuditRecordSBean.logMessageReceiptInNewTransaction(MessageAuditRecordSBean.java:48)
        at sun.reflect.GeneratedMethodAccessor142.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:324)
        at org.jboss.invocation.Invocation.performCall(Invocation.java:345)
        at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:214)
        at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:149)
        at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:154)
        at org.jboss.webservice.server.ServiceEndpointInterceptor.invoke(ServiceEndpointInterceptor.java:54)
        at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:48)
        at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:105)
        at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:389)
        at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)
        at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:139)
        at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)
        at org.jboss.ejb.plugins.CleanShutdownInterceptor.invoke(CleanShutdownInterceptor.java:264)
        at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
        at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:624)
        at org.jboss.ejb.Container.invoke(Container.java:873)
        at org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invoke(BaseLocalProxyFactory.java:415)
        at org.jboss.ejb.plugins.local.StatelessSessionProxy.invoke(StatelessSessionProxy.java:88)
        at $Proxy555.logMessageReceiptInNewTransaction(Unknown Source)
        at uk.co.abacus.jabs.msg.auditlogging.AbstractDatabaseAuditor.logJMSMessageReceived(AbstractDatabaseAuditor.java:116)
        at uk.co.abacus.jabs.msg.jms.JABSProxyMDBean.onMessage(JABSProxyMDBean.java:93)
        at sun.reflect.GeneratedMethodAccessor141.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:324)
        at org.jboss.invocation.Invocation.performCall(Invocation.java:345)
        at org.jboss.ejb.MessageDrivenContainer$ContainerInterceptor.invoke(MessageDrivenContainer.java:475)
        at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:149)
        at org.jboss.ejb.plugins.MessageDrivenInstanceInterceptor.invoke(MessageDrivenInstanceInterceptor.java:101)
        at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:48)
        at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:105)
        at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:335)
        at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)
        at org.jboss.ejb.plugins.RunAsSecurityInterceptor.invoke(RunAsSecurityInterceptor.java:94)
        at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)
        at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
        at org.jboss.ejb.MessageDrivenContainer.internalInvoke(MessageDrivenContainer.java:389)
        at org.jboss.ejb.Container.invoke(Container.java:873)
        at org.jboss.ejb.plugins.jms.JMSContainerInvoker.invoke(JMSContainerInvoker.java:1077)
        at org.jboss.ejb.plugins.jms.JMSContainerInvoker$MessageListenerImpl.onMessage(JMSContainerInvoker.java:1379)
        at org.jboss.jms.asf.StdServerSession.onMessage(StdServerSession.java:256)
        at org.jboss.mq.SpyMessageConsumer.sessionConsumerProcessMessage(SpyMessageConsumer.java:904)
        at org.jboss.mq.SpyMessageConsumer.addMessage(SpyMessageConsumer.java:160)
        at org.jboss.mq.SpySession.run(SpySession.java:333)
      • locked <0x52d69070> (a java.util.LinkedList)
        at org.jboss.jms.asf.StdServerSession.run(StdServerSession.java:180)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:748)
        at java.lang.Thread.run(Thread.java:534)

      Attachments

        Activity

          People

            adrian.brock Adrian Brock (Inactive)
            jim.paterson Jim Paterson (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: