[jboss-jira] [JBoss JIRA] Updated: (JBAS-4177) ApplicationDeadlockException without deadlock

ApplicationDeadlockException without deadlock --------------------------------------------- Key: JBAS-4177 URL: http://jira.jboss.com/jira/browse/JBAS-4177 Project: JBoss Application Server Issue Type: Bug Security Level: Public(Everyone can see) Affects Versions: JBossAS-4.0.5.GA, JBossAS-4.0.2 Final Environment: Windows XP, JDK 1.5 Reporter: Robert Aufreiter Attachments: jboss4Test_ear_src.zip, log.zip In some cases JBoss throws an ApplicationDeadlockException although there is no real deadlock. When 2 different Threads with the same transaction (Trans) enter org.jboss.ejb.plugins.lock.NonReentrantLock.acquireReentrant(...) (of entity bean Eb), the first (Thr1) gets the lock and the second (Thr2) must wait because the Threads are different. When Thr2 starts to wait org.jboss.util.deadlock.DeadlockDetector.deadlockDetection(...) is called with Thr2's transaction (which is the same as that of Thr1). DeadlockDetector checks if the transaction waits (indirectly) for a lock which is held by itself. In our case Trans (from Thr2) waits for Eb and Eb is locked by Trans (from Thr1). As Trans is the same transaction (used by Thr1 and also by Thr2) Trans waits for the lock of Eb which is held be Trans itself, i.e. Trans waits for itself and an ApplicationDeadlockException is thrown. But in our case no deadlock exists: if Thr2 would not throw an Exception but just wait for the lock, the lock would be freed by Thr1 after some time, because Thr1 is not waiting for Thr2 (in a real deadlock both Threads must be waiting for each other) and Thr2 could continue. Two different Threads enter NonReentrantLock.acquireReentrant(...) with the same transaction if (e.g.) the first is a call to a NOT-read-only function and the second is a call to a read-only function of the same entity bean. In this case org.jboss.ejb.plugins.EntityInstanceInterceptor.invoke(...) does not set (and not clear) the transaction in the EntityEnterpriseContext for the read-only call and so the transaction of the NOT-read-only call (Thr1) is also used for the read-only call (Thr2). Thread1 Thread2 Eb.setXxx("value") Eb.getYyy() (read-only) EntityInstanceInterceptor.invoke EntityInstanceInterceptor.invoke sets transaction Trans in ctx does not change Trans of ctx NonReentrantLock.acquireReentrant NonReentrantLock.acquireReentrant locks Eb wait for Thread1 DeadlockDetector.deadlockDetection Trans waits for Eb locked by Trans -> ApplicationDeadlockException For a deadlock at least 2 different Objects must be locked. It is impossible to create a deadlock with only one lockable Object (Eb). So the ApplicationDeadlockException in our case is a bug. (But I am not sure whether it is in DeadlockDetector or NonReentrantLock or EntityInstanceInterceptor (or somewhere else).) log output of one ApplicationDeadlockException (reformated to make it easier to see that the 2 locks and the 2 transactions are the same): org.jboss.util.deadlock.ApplicationDeadlockException: Application deadlock detected, resource= org.jboss.ejb.plugins.lock.NonReentrantLock@900079, holder= TransactionImpl:XidImpl[FormatId=257, GlobalId=Xion017/785, BranchQual=, localId=785], waitingResource=org.jboss.ejb.plugins.lock.NonReentrantLock@900079, waitingResourceHolder=TransactionImpl:XidImpl[FormatId=257, GlobalId=Xion017/785, BranchQual=, localId=785] full Exception: 2007-03-02 12:46:06,375 ERROR [org.jboss.ejb.plugins.LogInterceptor] TransactionRolledbackLocalException in method: public abstract java.lang.String at.xion.app.appl.TstEb1Local.getFld3(), causedBy: org.jboss.util.deadlock.ApplicationDeadlockException: Application deadlock detected, resource=org.jboss.ejb.plugins.lock.NonReentrantLock@900079, holder=TransactionImpl:XidImpl[FormatId=257, GlobalId=Xion017/785, BranchQual=, localId=785], waitingResource=org.jboss.ejb.plugins.lock.NonReentrantLock@900079, waitingResourceHolder=TransactionImpl:XidImpl[FormatId=257, GlobalId=Xion017/785, BranchQual=, localId=785] at org.jboss.util.deadlock.DeadlockDetector.deadlockDetection(DeadlockDetector.java:69) at org.jboss.ejb.plugins.lock.NonReentrantLock.acquireReentrant(NonReentrantLock.java:150) at org.jboss.ejb.plugins.lock.NonReentrantLock.attempt(NonReentrantLock.java:182) at org.jboss.ejb.plugins.EntityReentranceInterceptor.invoke(EntityReentranceInterceptor.java:94) at org.jboss.ejb.plugins.EntityInstanceInterceptor.invoke(EntityInstanceInterceptor.java:276) at org.jboss.ejb.plugins.EntityLockInterceptor.invoke(EntityLockInterceptor.java:104) at org.jboss.ejb.plugins.EntityCreationInterceptor.invoke(EntityCreationInterceptor.java:68) at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:63) at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:121) at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:350) at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:181) at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:168) at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:205) at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:136) at org.jboss.ejb.EntityContainer.internalInvoke(EntityContainer.java:527) at org.jboss.ejb.Container.invoke(Container.java:954) at org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invoke(BaseLocalProxyFactory.java:430) at org.jboss.ejb.plugins.local.EntityProxy.invoke(EntityProxy.java:65) at $Proxy57.getFld3(Unknown Source) at at.xion.app.appl.TstSb1Bean.tstFct2(TstSb1Bean.java:49) at sun.reflect.GeneratedMethodAccessor76.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.jboss.invocation.Invocation.performCall(Invocation.java:359) at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:237) at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:158) at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:169) at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:63) at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:121) at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:350) at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:181) at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:168) at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:205) at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:136) at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:648) at org.jboss.ejb.Container.invoke(Container.java:954) at org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invoke(BaseLocalProxyFactory.java:430) at org.jboss.ejb.plugins.local.StatelessSessionProxy.invoke(StatelessSessionProxy.java:103) at $Proxy58.tstFct2(Unknown Source) at org.apache.jsp.tst2_jsp$1.run(tst2_jsp.java:73) We found this problem in an productive application on JBoss 4.0.2, where it (ApplicationDeadlockException) occures approximatly ones a day, caused by different users accessing the same resource at the same time. I reproduced it on JBoss 4.0.5 with a small test-application (JBoss4Test.ear): (This contains all changes I made to the JBoss installation.) extracted jboss-4.0.5.GA.zip added "set JAVA_HOME=C:\java\jdk1.5.0_08" as first line to jboss-4.0.5.GA\bin\run.bat Changed line 405 <locking-policy>org.jboss.ejb.plugins.lock.QueuedPessimisticEJBLock</locking-policy> to <locking-policy>org.jboss.ejb.plugins.lock.JDBCOptimisticLock</locking-policy> in jboss-4.0.5.GA\server\default\conf\standardjboss.xml in section <container-name>Standard CMP 2.x EntityBean</container-name>. started JBoss (run.bat) shutdown JBoss (<CTRL>+C) cd jboss-4.0.5.GA/server/default/data/hypersonic java -classpath ..\..\lib\hsqldb.jar org.hsqldb.util.DatabaseManager jdbc:hsqldb:C:\test\jboss-4.0.5.GA\server\default\data\hypersonic\localDB create table tstTbl1 (fld1 varchar, fld2 varchar, fld3 varchar) insert into tstTbl1 values('row1col1', 'row1col2', 'row1col3') insert into tstTbl1 values('row2col1', 'row2col2', 'row2col3') insert into tstTbl1 values('row3col1', 'row3col2', 'row3col3') commit select * from tsttbl1 copied JBoss4Test.ear to jboss-4.0.5.GA\server\default\deploy\ started JBoss (run.bat) opened "http://localhost:8080/tst/tst2.jsp" and opened "http://localhost:8080/tst/tst1.jsp" in InternetExplorer (2 Windows; simultanously (tst1.jsp opened while tst2.jsp was still loading)) shutdown JBoss (<CTRL>+C) The log and JBoss4Test.ear+source are in the attachment. What is your JBoss Version? 4.0.5 (also found on 4.0.2) Have you tried the latest and greatest? Yes (4.0.5 is the latest stable (5.0.0 is still beta)) What version of Java are you using? 1.5.0_08 Have you tried the latest JVM or a different vendor? Yes (also tried 1.6.0) What Operating System are you using? Windows XP Do you have the correct patches to run the virtual machine? downloaded 1.6.0 a few days ago -> I'm quite sure there have not been any updates since Do you have a known OS issue? I don't think so What database/thirdparty jars are you using? none (hypersonic, which is included in JBoss) Have you asked the thirdparty for help? there is no third party What configuration changes did you make to JBoss? set JAVA_HOME JDBCOptimisticLock created table "tstTbl1" Does it work if you don't make those changes? No Why did you make that change? JAVA_HOME is necessary to start JBoss it seems that with QueuedPessimisticEJBLock the special case where the problem is possible cannot be reached tstTbl1 is needed by the test-application (an entity bean is needed to reproduce the problem) Where did you get the information about that change? could not reproduce it on new installed JBoss at first -> found the difference to the one used in production (QueuedPessimisticEJBLock -> JDBCOptimisticLock) What is your problem? JBoss throws an ApplicationDeadlockException but there is no deadlock (users get error messages even though their threads could complete correctly) Could you hope to answer the question from the information you post? Yes (my post contains an application which reproduces the problem, the names of the JBoss-classes where it occures and an description how it is possible and arises) Did you ask a colleague about the problem first? This can save a lot of embarrassment and wasted time. No, because I am the colleague my colleagues asked about this problem. What error message do you see? 2007-03-02 12:46:06,375 ERROR [org.jboss.ejb.plugins.LogInterceptor] TransactionRolledbackLocalException in method: public abstract java.lang.String at.xion.app.appl.TstEb1Local.getFld3(), causedBy: org.jboss.util.deadlock.ApplicationDeadlockException: Application deadlock detected, resource=org.jboss.ejb.plugins.lock.NonReentrantLock@900079, holder=TransactionImpl:XidImpl[FormatId=257, GlobalId=Xion017/785, BranchQual=, localId=785], waitingResource=org.jboss.ejb.plugins.lock.NonReentrantLock@900079, waitingResourceHolder=TransactionImpl:XidImpl[FormatId=257, GlobalId=Xion017/785, BranchQual=, localId=785] Post the full stacktrace. is above in the post Is that the first error message? Yes. Are there any related WARN messages? No, there are no warnings (" WARN ") in the whole log. Have you tried searching for that error message? Yes, I searched for "ApplicationDeadlockException" on JBoss.org JIRA but the 4 entries found do not concern this problem. (I also searched on Google but didn't find anything concerning exactly this bug.) Is it actually a JBoss error message? Yes, it's thrown in org.jboss.util.deadlock.DeadlockDetector.deadlockDetection(...) line 69 Have you included the deployment descriptors for the application with the problem? Yes, I includes the whole application. What did you expect to happen? I expected that no deadlock-Exception is thrown when there is no deadlock. Why did you expect that behaviour? Good applications don't throw an Exception for an error when the error did not occure. How does your application differ from the many examples that work? I don't know if our application differs from all working examples. This Problem occures only in a very special case (read-only-fct + not-read-only-fct and called nearly at the same time in correct order on the same instance of an entity bean in a JBoss with JDBCOptimisticLock). It is possible that some "working" excamples could produce the same problem but it was not found because it occures to seldom. Have you enabled DEBUG or TRACE logging to see what is really happening? Yes, and I also added some more log-statements and recombiled JBoss (4.0.2) but this is not included in this post (some GB of output and already deleted). Post the log from around the time you have the problem. complete log of the reproduction of the problem is included What steps did you take to isolate the problem? reproduced it on copy of productiv environment, wrote minimal application which reproduces the problem Do you know what configuration option or api calls causes the problem? Yes, config-changes and called JBoss functions causing the problem are above in this post If you are reporting a "bug", how do you know it is a bug? JBoss wrongly detects a deadlock. Throwing an Exception for an error which did not occure is a bug. Can you quote chapter and verse from the specification? No, throwing an Exception for an error which did not occure would be a bug in any application (and has nothing to do with the J2EE-specification). Do you have a simple test that reproduces the "bug"? Yes, test-application is included. Did you search to see whether the "bug" is already fixed? Yes, already mentioned above. How do I add attachments (JBoss4Test.ear for reproducing the bug and logs)?