Hi

Using Hibernate Core 3.3.1.GA and Hibernate Annotations 3.4.0.GA on MySQL database. See the essential part of my hibernate.cfg.xml below.

I have a User and a Group entity in my hibernate model. User contains a list of Groups:
@ManyToMany(fetch = FetchType.EAGER)
@Fetch(value = FetchMode.SUBSELECT)
@JoinTable(name = "UserGroups")
private List<Group> groups = new ArrayList<Group>();

At one point in my application I have a new User object (user) that has an existing Group object in its list of groups. I want to save it with the following code:
Session session = sessionFactory.getCurrentSession();
session.merge(user);
When the session is flushed/closed (when the Glassfish CMT closes i guess) an "insert into User" and a "insert into UserGroups" is invoked (as expected). But the "insert into UserGroups" hangs for a long time and it all ends in an "java.sql.BatchUpdateException: Lock wait timeout exceeded; try restarting transaction"-exception. See the log "------------------ log with "session.merge()" ------------------------------" below. I cannot figure out why this error occurs.

I have tried execute the same statements using pure SQL:
Session session = getCurrentSession();
SQLQuery q = session.createSQLQuery("insert into User (id, version, description, name, superior_pid, userName) values ('" + user.getID() + "', 0, '" + user.getDescription() + "', '" + user.getName() + "', null, '" + user.getUserName() + "')");
q.executeUpdate();
q = session.createSQLQuery("insert into UserGroups (User_pid, groups_pid) values (14, 50)");
q.executeUpdate();
The user_pid = 14 corresponded to the user created in the first SQL, and groups_pid = 50 corresponds to the group added to the User in the real case. So all in all the SQL queries inserts the exact same data into the database as the "session.merge()" does, but now it does NOT fail. See the log "------------------ log with "SQLQueries" ------------------------------" below.

Can anyone help me with an explanation on why the problem occurs when using "session.merge", and why it then does not occur when using corresponding "SQL inserts"???

Regards, Per Steffensen

------------------ hibernate.cfg.xml - start -----------------------------------
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-configuration PUBLIC
"-//Hibernate/Hibernate Configuration DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd">
<hibernate-configuration>
<session-factory >
<!-- <property name="hibernate.connection.driver_class">com.mysql.jdbc.Driver</property>-->
<property name="hibernate.show_sql">true</property>
<property name="hibernate.format_sql">true</property>

<property name="hibernate.connection.password">liace123</property>
<property name="hibernate.connection.datasource">jdbc/MySQLResource</property>
<property name="hibernate.connection.username">root</property>
<!---->
<property name="hibernate.transaction.manager_lookup_class">org.hibernate.transaction.SunONETransactionManagerLookup</property>
<property name="hibernate.transaction.factory_class">org.hibernate.transaction.CMTTransactionFactory</property>
<property name="hibernate.current_session_context_class">jta</property>

<!-- <property name="hibernate.hbm2ddl.auto">update</property>-->
<property name="hibernate.dialect">org.hibernate.dialect.MySQL5InnoDBDialect</property>
<snip>
<mapping class="com.tlt.em.common.domainmodel.report.User"/>
<mapping class="com.tlt.em.common.domainmodel.user.Group"/>
<snip>
</session-factory>
</hibernate-configuration>
------------------ hibernate.cfg.xml - end -----------------------------------

------------------ log with "session.merge()" - start ------------------------------
[#|2009-12-16T10:41:18.394+0100|INFO|sun-appserver2.1|javax.enterprise.system.stream.out|_ThreadID=19;_ThreadName=p: thread-pool-1; w: 3;|
Hibernate:
insert
into
User
(id, version, description, name, superior_pid, userName)
values
(?, ?, ?, ?, ?, ?)|#]

[#|2009-12-16T10:41:23.042+0100|INFO|sun-appserver2.1|javax.enterprise.system.stream.out|_ThreadID=19;_ThreadName=p: thread-pool-1; w: 3;|
Hibernate:
insert
into
UserGroups
(User_pid, groups_pid)
values
(?, ?)|#]

[#|2009-12-16T10:42:14.751+0100|WARNING|sun-appserver2.1|javax.enterprise.system.stream.err|_ThreadID=19;_ThreadName=p: thread-pool-1; w: 3;_RequestID=78c91f
5c-3f4b-4b77-8cf7-6274d344553d;|
175237 [p: thread-pool-1; w: 3] WARN org.hibernate.util.JDBCExceptionReporter - SQL Error: 1205, SQLState: 41000
|#]

[#|2009-12-16T10:42:14.751+0100|WARNING|sun-appserver2.1|javax.enterprise.system.stream.err|_ThreadID=19;_ThreadName=p: thread-pool-1; w: 3;_RequestID=78c91f
5c-3f4b-4b77-8cf7-6274d344553d;|175237 [p: thread-pool-1; w: 3] ERROR org.hibernate.util.JDBCExceptionReporter - Lock wait timeout exceeded; try restarting t
ransaction
|#]

[#|2009-12-16T10:42:14.752+0100|WARNING|sun-appserver2.1|javax.enterprise.system.stream.err|_ThreadID=19;_ThreadName=p: thread-pool-1; w: 3;_RequestID=78c91f
5c-3f4b-4b77-8cf7-6274d344553d;|175238 [p: thread-pool-1; w: 3] ERROR org.hibernate.event.def.AbstractFlushingEventListener - Could not synchronize database state with session
|#]

[#|2009-12-16T10:42:14.758+0100|WARNING|sun-appserver2.1|javax.enterprise.system.stream.err|_ThreadID=19;_ThreadName=p: thread-pool-1; w: 3;_RequestID=78c91f5c-3f4b-4b77-8cf7-6274d344553d;|org.hibernate.exception.GenericJDBCException: Could not execute JDBC batch update
at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:126)
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:114)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:275)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:266)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:171)
at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1027)
at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:365)
at org.hibernate.transaction.CacheSynchronization.beforeCompletion(CacheSynchronization.java:88)
at com.sun.jts.jta.SynchronizationImpl.before_completion(SynchronizationImpl.java:99)
at com.sun.jts.CosTransactions.RegisteredSyncs.distributeBefore(RegisteredSyncs.java:158)
at com.sun.jts.CosTransactions.TopCoordinator.beforeCompletion(TopCoordinator.java:2548)
at com.sun.jts.CosTransactions.CoordinatorTerm.commit(CoordinatorTerm.java:278)
at com.sun.jts.CosTransactions.TerminatorImpl.commit(TerminatorImpl.java:250)
at com.sun.jts.CosTransactions.CurrentImpl.commit(CurrentImpl.java:623)
at com.sun.jts.jta.TransactionManagerImpl.commit(TransactionManagerImpl.java:309)
at com.sun.enterprise.distributedtx.J2EETransactionManagerImpl.commit(J2EETransactionManagerImpl.java:1029)
at com.sun.enterprise.distributedtx.J2EETransactionManagerOpt.commit(J2EETransactionManagerOpt.java:398)
at com.sun.ejb.containers.BaseContainer.completeNewTx(BaseContainer.java:3817)
at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:3596)
at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:1379)
at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:1316)
at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:205)
at com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:83)
at $Proxy29.saveUser(Unknown Source)
at com.tlt.em.ejb.userhandler.UserRPCMessageHandler.saveUser(UserRPCMessageHandler.java:124)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.tlt.em.ejb.common.BaseTextMessageMDB.request(BaseTextMessageMDB.java:310)
at com.tlt.em.ejb.common.BaseTextMessageMDB.invokeLocalBusinessMethod(BaseTextMessageMDB.java:392)
at com.tlt.em.ejb.common.BaseTextMessageMDB.invokeBusinessMethod(BaseTextMessageMDB.java:382)
at com.tlt.em.ejb.common.BaseTextMessageMDB.invokeBusinessMethodAndReply(BaseTextMessageMDB.java:234)
at com.tlt.em.ejb.common.BaseTextMessageMDB$InvokeBusinessMethodAndReplyPrivilegedAction.run(BaseTextMessageMDB.java:222)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:396)
at com.tlt.em.ejb.common.BaseTextMessageMDB.invokeBusinessMethodAndReplyAs(BaseTextMessageMDB.java:193)
at com.tlt.em.ejb.common.BaseTextMessageMDB.notifyNewMessage(BaseTextMessageMDB.java:175)
at com.tlt.em.ejb.common.BaseTextMessageMDB.handleNewMessage(BaseTextMessageMDB.java:141)
at com.tlt.em.ejb.common.BaseTextMessageMDB.onMessage(BaseTextMessageMDB.java:80)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.sun.enterprise.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:1011)
at com.sun.enterprise.security.SecurityUtil.invoke(SecurityUtil.java:175)
at com.sun.ejb.containers.BaseContainer.invokeTargetBeanMethod(BaseContainer.java:2920)
at com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:4011)
at com.sun.ejb.containers.MessageBeanContainer.deliverMessage(MessageBeanContainer.java:1111)
at com.sun.ejb.containers.MessageBeanListenerImpl.deliverMessage(MessageBeanListenerImpl.java:74)
at com.sun.enterprise.connectors.inflow.MessageEndpointInvocationHandler.invoke(MessageEndpointInvocationHandler.java:179)
at $Proxy36.onMessage(Unknown Source)
at com.sun.genericra.inbound.async.DeliveryHelper.deliverMessage(DeliveryHelper.java:301)
at com.sun.genericra.inbound.async.DeliveryHelper.deliver(DeliveryHelper.java:196)
at com.sun.genericra.inbound.async.DeliveryHelper.deliver(DeliveryHelper.java:186)
at com.sun.genericra.inbound.async.EndpointConsumer.consumeMessage(EndpointConsumer.java:177)
at com.sun.genericra.inbound.async.MessageListener.onMessage(MessageListener.java:56)
at org.apache.activemq.ActiveMQSession.run(ActiveMQSession.java:735)
at org.apache.activemq.ActiveMQQueueSession.run(ActiveMQQueueSession.java:355)
at com.sun.genericra.inbound.async.WorkImpl.run(WorkImpl.java:53)
at com.sun.enterprise.connectors.work.OneWork.doWork(OneWork.java:76)
at com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:555)
Caused by: java.sql.BatchUpdateException: Lock wait timeout exceeded; try restarting transaction
at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1693)
at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1108)
at com.mysql.jdbc.jdbc2.optional.StatementWrapper.executeBatch(StatementWrapper.java:719)
at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
... 61 more
|#]
------------------ log with "session.merge()" - end ------------------------------

------------------ log with "SQLQueries" - start ------------------------------
[#|2009-12-16T10:57:05.397+0100|INFO|sun-appserver2.1|javax.enterprise.system.stream.out|_ThreadID=41;_ThreadName=p: thread-pool-1; w: 6;|
Hibernate:
insert
into
User
(id, version, description, name, superior_pid, userName)
values
('769155b8-8304-493c-95b3-88aa288bfe4d', 0, 'asldkjflsk', 'wefsdklkj', null, 'fekjlskdfj')|#]

[#|2009-12-16T10:57:07.069+0100|INFO|sun-appserver2.1|javax.enterprise.system.stream.out|_ThreadID=41;_ThreadName=p: thread-pool-1; w: 6;|
Hibernate:
insert
into
UserGroups
(User_pid, groups_pid)
values
(14, 50)|#]
------------------ log with "SQLQueries" - end ------------------------------

I guessed that it might be because the inserts was executed in a batch when "session.merge", so I decided to try to execute the SQL's in a batch (se code below). But it also works/succeeds. So I guess that the batch thing is not the problem.

session.doWork(new Work() { public void execute(Connection conn) {
Statement stmt = null;
try {
stmt = conn.createStatement();
stmt.addBatch("insert into User (id, version, description, name, superior_pid, userName) values ('" + user.getID() + "', 0, '" + user.getDescription() + "', '" + user.getName() + "', null, '" + user.getUserName() + "')");
stmt.addBatch("insert into UserGroups (User_pid, groups_pid) values (18, 50)");
stmt.executeBatch();
} catch (Exception e) {
e.printStackTrace(System.out);
} finally {
if (stmt != null) try {stmt.close();} catch (Exception e) {}
}
} } );

I was trying to have a look at the MySQL query log in the different cases and saw the following:

With doWork/SQL/batch:
091216 12:55:38 5148 Query /* */ insert into User (id, version, description, name, superior_pid, userName) values ('d0c9688d-03ff-4f7a-83e9-1c009894e165', 0, 'asdf', 'asdf', null, 'user20')
5148 Query /* */ insert into UserGroups (User_pid, groups_pid) values (20, 50)
091216 12:55:40 5148 Query /* */ XA END 0x4800000052502e977065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c5033373030,0x7065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c50333730302c00,0x4a5453
5148 Query /* */ XA COMMIT 0x4800000052502e977065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c5033373030,0x7065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c50333730302c00,0x4a5453 ONE PHASE

With session.merge:
091216 12:59:34 5143 Query /* */ insert into User (id, version, description, name, superior_pid, userName) values ('b02a1eb9-572a-483f-983c-e39dddcbf016', 0, 'asdf', 'asdf', null, 'user21')
5145 Query /* */ SELECT @@session.tx_isolation
5145 Query /* */ insert into UserGroups (User_pid, groups_pid) values (21, 50)
091216 13:00:25 5143 Query /* */ XA END 0x5900000052502e977065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c5033373030,0x7065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c50333730302c00,0x4a5453
5143 Query /* */ XA ROLLBACK 0x5900000052502e977065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c5033373030,0x7065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c50333730302c00,0x4a5453

They are very simular, but I noticed the "SELECT @@session.tx_isolation" between "insert into User" and "insert into UserGroups" in the "session.merge" case. I was trying some different things, and ended up finding out the this will work:
try {session.connection().getTransactionIsolation();} catch (Exception e) {}
session.merge(user);
Remember that "session.merge(user);" alone does NOT work.

For...
try {session.connection().getTransactionIsolation();} catch (Exception e) {}
session.merge(user);
...I get the following in MySQL query log:
091216 13:41:31 5156 Query /* */ SELECT @@session.tx_isolation
091216 13:41:32 5156 Query /* */ insert into User (id, version, description, name, superior_pid, userName) values ('2a733b3f-e42a-4322-a9be-84524e04dd7d', 0, 'asdf', 'asdf', null, 'usernext')
5156 Query /* */ insert into UserGroups (User_pid, groups_pid) values (30, 50)
5156 Query /* */ XA END 0xfa00000052502e977065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c5033373030,0x7065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c50333730302c00,0x4a5453
5156 Query /* */ XA COMMIT 0xfa00000052502e977065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c5033373030,0x7065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c50333730302c00,0x4a5453 ONE PHASE

It seems like "try {session.connection().getTransactionIsolation();} catch (Exception e) {}" forces the "SELECT @@session.tx_isolation" up before "insert into User" and that it makes the problem not occur.

I interpret is as: Hibernate have a look at getTransactionIsolation() between "insert into User" and "insert into UserGroups" and that makes the thing fail. Why Hibernate does getTransactionIsolation() i dont know. Why MySQL fails on that scenario is a huge mystery for me! Any attempt to explain is very welcome!

I have tried adding an "try {session.connection().getTransactionIsolation();} catch (Exception e) {}" in between the two SQL's to force a "SELECT @@session.tx_isolation" between "insert into User" and "insert into UserGroups":
SQLQuery q = session.createSQLQuery("insert into User (id, version, description, name, superior_pid, userName) values ('" + user.getID() + "', 0, '" + user.getDescription() + "', '" + user.getName() + "', null, '" + user.getUserName() + "')");
q.executeUpdate();
try {session.connection().getTransactionIsolation();} catch (Exception e) {}
q = session.createSQLQuery("insert into UserGroups (User_pid, groups_pid) values (41, 50)");
q.executeUpdate();

That does not make it fail. So I guess there is more to it than just a getTransactionIsolation() in between the two inserts.

MySQL query log in this case is:
091216 14:25:10 5229 Query /* */ insert into User (id, version, description, name, superior_pid, userName) values ('fb4e320e-3b2e-4bbd-ba40-1173d0dab675', 0, 'asdf', 'asdf', null, 'densidsteslutter')
091216 14:25:11 5229 Query /* */ SELECT @@session.tx_isolation
091216 14:25:13 5229 Query /* */ insert into UserGroups (User_pid, groups_pid) values (41, 50)
091216 14:25:15 5229 Query /* */ XA END 0x4b02000052502e977065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c5033373030,0x7065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c50333730302c00,0x4a5453
5229 Query /* */ XA COMMIT 0x4b02000052502e977065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c5033373030,0x7065722d7374656666656e73656e732d6d6163626f6f6b2d70726f2e6c6f63616c2c7365727665722c50333730302c00,0x4a5453 ONE PHASE

I know this is pretty old thread, but I had a same problem and this was the first relevant thing I've found in google search.

The cause of this problem is quite well explained here:

http://java.net/jira/browse/GLASSFISH-8402

So to sum it up, hibernate is flushing session within the org.hibernate.transaction.CacheSynchronization.beforeCompletion method. This method is called just before completing transaction. However code executed there gets different jdbc connection (which is not attached to transaction), thus there are two jdbc connections competing for the same object in db - which results in the deadlock you've encountered.

So the solution is to check Allow Non Component Callers: option in advanced tab of given JDBC Connection pool in glassfish.