JBoss 6.1 - Deadlock with Transaction propagation over JRMP and Hibernate
azinemanas Oct 7, 2011 2:08 PMI have two remote EJBs using transaction propagation over JRMP.
The first EJB is very simple and only invokes the second EJB using jndi:
{code}
@Stateless
public class MultiOutEJB implements IMultiOutEJB {
public void testOut() {
IMultiInEJB remoteEJB = getRemoteEJB();
remoteEJB.testIn();
...
}
}
{code}
In the second EJB I use JPA (Hibernate) to update a database:
{code}
@Stateless
public class MultiInEJB implements IMultiInEJB {
@PersistenceContext
private EntityManager em;
public void testIn() {
Parameter p1 = getParameterById(paramId);
p1.setValue("ABC");
em.flush();
em.close();
Parameter p2 = getParameterById(paramId);
p2.setValue("123");
}
}
{code}
The problem is that the modification of p2 (which is made by Hibernate behind the scene because there is not a explicit flush) apparently is made in a new transaction. Given that the original transaction is not commited the two updates caused a deadlock at the database level.
The stacktrace is:
{code}
23:03:01,636 WARN [org.hibernate.util.JDBCExceptionReporter] SQL Error: 1205, SQLState: 41000
23:03:01,637 ERROR [org.hibernate.util.JDBCExceptionReporter] Lock wait timeout exceeded; try restarting transaction
23:03:01,640 ERROR [org.hibernate.ejb.AbstractEntityManagerImpl] Unable to mark for rollback on PersistenceException: : java.lang.IllegalStateException: ARJUNA-24035 No such transaction!
at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.setRollbackOnly(BaseTransaction.java:183) [:6.1.0.Final]
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.setRollbackOnly(BaseTransactionManagerDelegate.java:123) [:6.1.0.Final]
at org.hibernate.ejb.AbstractEntityManagerImpl.markAsRollback(AbstractEntityManagerImpl.java:964) [:3.6.7.Final]
at org.hibernate.ejb.AbstractEntityManagerImpl.handlePersistenceException(AbstractEntityManagerImpl.java:1127) [:3.6.7.Final]
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1216) [:3.6.7.Final]
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1148) [:3.6.7.Final]
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1154) [:3.6.7.Final]
at org.hibernate.ejb.AbstractEntityManagerImpl$3.mapManagedFlushFailure(AbstractEntityManagerImpl.java:1068) [:3.6.7.Final]
at org.hibernate.transaction.synchronization.CallbackCoordinator.beforeCompletion(CallbackCoordinator.java:122) [:3.6.7.Final]
at org.hibernate.transaction.synchronization.HibernateSynchronizationImpl.beforeCompletion(HibernateSynchronizationImpl.java:51) [:3.6.7.Final]
at com.arjuna.ats.internal.jta.resources.jts.orbspecific.SynchronizationImple.before_completion(SynchronizationImple.java:116) [:6.1.0.Final]
at com.arjuna.ArjunaOTS.ManagedSynchronizationPOATie.before_completion(ManagedSynchronizationPOATie.java:53) [:6.1.0.Final]
at com.arjuna.ArjunaOTS.ManagedSynchronizationPOA._invoke(ManagedSynchronizationPOA.java:46) [:6.1.0.Final]
at org.jacorb.poa.RequestProcessor.invokeOperation(Unknown Source) [:6.1.0.Final]
at org.jacorb.poa.RequestProcessor.process(Unknown Source) [:6.1.0.Final]
at org.jacorb.poa.RequestProcessor.run(Unknown Source) [:6.1.0.Final]
Caused by: java.lang.NullPointerException
at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.setRollbackOnly(BaseTransaction.java:179) [:6.1.0.Final]
... 15 more
23:03:01,652 WARN [com.arjuna.ats.jts] ARJUNA-22024 ArjunaTransactionImple.doBeforeCompletion caught exception: org.omg.CORBA.UNKNOWN: Server-side Exception: vmcid: 0x0 minor code: 0 completed: No
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [:1.6.0_27]
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39) [:1.6.0_27]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27) [:1.6.0_27]
at java.lang.reflect.Constructor.newInstance(Constructor.java:513) [:1.6.0_27]
at org.jacorb.orb.SystemExceptionHelper.read(Unknown Source) [:6.1.0.Final]
at org.jacorb.orb.ReplyReceiver.getReply(Unknown Source) [:6.1.0.Final]
at org.jacorb.orb.Delegate.invoke_internal(Unknown Source) [:6.1.0.Final]
at org.jacorb.orb.Delegate.invoke(Unknown Source) [:6.1.0.Final]
at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:457) [:1.6.0_27]
at org.omg.CosTransactions._SynchronizationStub.before_completion(_SynchronizationStub.java:33) [:6.1.0.Final]
at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.doBeforeCompletion(ArjunaTransactionImple.java:1458) [:6.1.0.Final]
at com.arjuna.ats.internal.jts.orbspecific.interposition.coordinator.ServerTransaction.doBeforeCompletion(ServerTransaction.java:517) [:6.1.0.Final]
at com.arjuna.ats.internal.jts.orbspecific.interposition.coordinator.ServerTransaction.doPrepare(ServerTransaction.java:165) [:6.1.0.Final]
at com.arjuna.ats.internal.jts.orbspecific.interposition.resources.arjuna.ServerTopLevelAction.prepare(ServerTopLevelAction.java:188) [:6.1.0.Final]
at org.omg.CosTransactions.ResourcePOATie.prepare(ResourcePOATie.java:63) [:6.1.0.Final]
at org.omg.CosTransactions.ResourcePOA._invoke(ResourcePOA.java:102) [:6.1.0.Final]
at org.jacorb.poa.RequestProcessor.invokeOperation(Unknown Source) [:6.1.0.Final]
at org.jacorb.poa.RequestProcessor.process(Unknown Source) [:6.1.0.Final]
at org.jacorb.poa.RequestProcessor.run(Unknown Source) [:6.1.0.Final]
23:03:01,655 WARN [com.arjuna.ats.arjuna] ARJUNA-12080 Transaction 0:ffffc0a803a9:12ce:4e8d0bb3:281 marked as rollback only. Will abort.
23:03:01,708 WARN [jacorb.poa.controller] rid: 42 opname: rollback cannot process request, because object doesn't exist
23:03:01,708 WARN [jacorb.poa.controller] rid: 42 opname: rollback request rejected with exception:
{code}
Here is the database (MySQL) log:
{code}
XA START 0x00000000000000000000ffffc0a803a9000012ce4e8d13c00000060c31,0x00000000000000000000ffffc0a803a90000126a4e8d138b00000431,0x20000
select ... from PARAMETROS parametro0_ where parametro0_.nombre='PARAMETRO_TEST_MULTI' limit 2
update PARAMETROS set codigoEntidad=null, nombre='PARAMETRO_TEST_MULTI', valor='ABC' where id=120
select ... from PARAMETROS parametro0_ where parametro0_.nombre='PARAMETRO_TEST_MULTI' limit 2
XA END 0x00000000000000000000ffffc0a803a9000012ce4e8d13c00000060c31,0x00000000000000000000ffffc0a803a9000012ce4e8d13c000000611,0x20000
XA PREPARE 0x00000000000000000000ffffc0a803a9000012ce4e8d13c00000060c31,0x00000000000000000000ffffc0a803a9000012ce4e8d13c000000611,0x20000
update PARAMETROS set codigoEntidad=null, nombre='PARAMETRO_TEST_MULTI', valor='123' where id=120
{code}
The two updates access the same row. Given that two updates can´t deadlock if are made in the same transaction, thats means the second updateis executed in other transaction.
I don´t now if this is an error of Hibernate or JBossTS, or maybe a configuration error.
My workaround is put a flush in all remote operations.