JPA concurrent transactions

Question

I'm having a problem with concurrent transactions using JPA-1.0, Hibernate and MySQL 5.0.84 (innoDB tables) and also Postgres 8.1.11 (different database for different client). I don't know if I'm missing something regarding config, as I've read specs on JPA transactions, and according to the problem I have, I need to specify a specific isolation level for the transaction annotation. This I did, but it just turns off the transaction all together, so nothing gets persisted/updated.

What I'm doing is, initiate http posts to a web server (tomcat in my case), which then attempts to spawn multiple DB transactions as the http requests come in. Each transaction comprises of 1 insert and 2 updates. The problem always seem to occur on the final update though, which is based on the previous insert. So, I insert record A, then update record B which is a foreign key to record A.

The following is the logging I obtain upon performing a single http request:

org.springframework.orm.jpa.JpaTransactionManager:365 - Creating new transaction with name [biz.cytrus.overlord.v2.core.ExecutionLogAPI.create]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
org.springframework.orm.jpa.JpaTransactionManager:323 - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@221f81] for JPA transaction
org.springframework.orm.jpa.JpaTransactionManager:355 - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@9f5742]
org.springframework.orm.jpa.JpaTransactionManager:752 - Initiating transaction commit
org.springframework.orm.jpa.JpaTransactionManager:462 - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@221f81]
org.springframework.orm.jpa.JpaTransactionManager:548 - Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@221f81] after transaction
org.springframework.orm.jpa.EntityManagerFactoryUtils:329 - Closing JPA EntityManager

The following is the logging I obtain upon performing multiple http requests concurrently:

org.hibernate.util.JDBCExceptionReporter:357 - SQL Error: 1213, SQLState: 40001
org.hibernate.util.JDBCExceptionReporter:454 - Deadlock found when trying to get lock; try restarting transaction
org.hibernate.event.def.AbstractFlushingEventListener:532 - Could not synchronize database state with session
org.hibernate.exception.LockAcquisitionException: Could not execute JDBC batch update
        at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:105)
        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:168)
        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.JDBCTransaction.commit(JDBCTransaction.java:137)
        at org.hibernate.ejb.TransactionImpl.commit(TransactionImpl.java:54)
        at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:467)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:754)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:723)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:375)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:120)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy66.create(Unknown Source)
        at biz.cytrus.overlord.v2.web.action.task.LogAction.createLogEntry(LogAction.java:84)
        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:592)
        at net.sourceforge.stripes.controller.DispatcherHelper$6.intercept(DispatcherHelper.java:442)
        at net.sourceforge.stripes.controller.ExecutionContext.proceed(ExecutionContext.java:158)
        at net.sourceforge.stripes.controller.BeforeAfterMethodInterceptor.intercept(BeforeAfterMethodInterceptor.java:113)
        at net.sourceforge.stripes.controller.ExecutionContext.proceed(ExecutionContext.java:155)
        at net.sourceforge.stripes.controller.ExecutionContext.wrap(ExecutionContext.java:74)
        at net.sourceforge.stripes.controller.DispatcherHelper.invokeEventHandler(DispatcherHelper.java:440)
        at net.sourceforge.stripes.controller.DispatcherServlet.invokeEventHandler(DispatcherServlet.java:278)
        at net.sourceforge.stripes.controller.DispatcherServlet.service(DispatcherServlet.java:160)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at net.sourceforge.stripes.controller.StripesFilter.doFilter(StripesFilter.java:247)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849)
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454)
        at java.lang.Thread.run(Thread.java:595)
Caused by: java.sql.BatchUpdateException: Deadlock found when trying to get lock; try restarting transaction
        at com.mysql.jdbc.ServerPreparedStatement.executeBatch(ServerPreparedStatement.java:657)
        at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:1723)
        at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
        at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
        ... 48 more
org.springframework.orm.jpa.JpaTransactionManager:893 - Initiating transaction rollback after commit exception
org.springframework.dao.CannotAcquireLockException: Could not execute JDBC batch update; SQL [update application_instances set application_id=?, create_date=?, for_ongoing_task=?, last_log_id=?, last_notified_date=?, name=?, param_string=?, application_status_id=?, status_date=? where id=?]; nested exception is org.hibernate.exception.LockAcquisitionException: Could not execute JDBC batch update
        at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:633)
        at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:97)
        at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:471)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:754)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:723)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:375)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:120)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy66.create(Unknown Source)
        at biz.cytrus.overlord.v2.web.action.task.LogAction.createLogEntry(LogAction.java:84)
        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:592)
        at net.sourceforge.stripes.controller.DispatcherHelper$6.intercept(DispatcherHelper.java:442)
        at net.sourceforge.stripes.controller.ExecutionContext.proceed(ExecutionContext.java:158)
        at net.sourceforge.stripes.controller.BeforeAfterMethodInterceptor.intercept(BeforeAfterMethodInterceptor.java:113)
        at net.sourceforge.stripes.controller.ExecutionContext.proceed(ExecutionContext.java:155)
        at net.sourceforge.stripes.controller.ExecutionContext.wrap(ExecutionContext.java:74)
        at net.sourceforge.stripes.controller.DispatcherHelper.invokeEventHandler(DispatcherHelper.java:440)
        at net.sourceforge.stripes.controller.DispatcherServlet.invokeEventHandler(DispatcherServlet.java:278)
        at net.sourceforge.stripes.controller.DispatcherServlet.service(DispatcherServlet.java:160)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at net.sourceforge.stripes.controller.StripesFilter.doFilter(StripesFilter.java:247)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849)
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454)
        at java.lang.Thread.run(Thread.java:595)
Caused by: org.hibernate.exception.LockAcquisitionException: Could not execute JDBC batch update
        at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:105)
        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:168)
        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.JDBCTransaction.commit(JDBCTransaction.java:137)
        at org.hibernate.ejb.TransactionImpl.commit(TransactionImpl.java:54)
        at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:467)
        ... 39 more
Caused by: java.sql.BatchUpdateException: Deadlock found when trying to get lock; try restarting transaction
        at com.mysql.jdbc.ServerPreparedStatement.executeBatch(ServerPreparedStatement.java:657)
        at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:1723)
        at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
        at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
        ... 48 more
org.springframework.orm.jpa.JpaTransactionManager:488 - Rolling back JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@7ca9bd]
org.springframework.orm.jpa.JpaTransactionManager:548 - Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@7ca9bd] after transaction
org.springframework.orm.jpa.EntityManagerFactoryUtils:329 - Closing JPA EntityManager

In attempting to solve this problem, I've tried to set the isolation level on the transaction annotation, but that results in no activity on the database:

org.springframework.orm.jpa.JpaTransactionManager:365 - Creating new transaction with name [biz.cytrus.overlord.v2.core.ExecutionLogAPI.create]: PROPAGATION_REQUIRED,ISOLATION_REPEATABLE_READ; ''
org.springframework.orm.jpa.JpaTransactionManager:323 - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@adddd6] for JPA transaction
org.springframework.orm.jpa.EntityManagerFactoryUtils:329 - Closing JPA EntityManager

I would really appreciate any assistance on how I could solve this issue.

Here's a snippet of the code in the method marked with the annotation @Transactional:

Task task = ongoingTaskAPI.findById(taskId);
ExecutionLog executionLog = new ExecutionLog();
executionLog.setStatusDate(new Date());
executionLog.setStatus(status);

        executionLog.setApplicationInstance(task.getApplicationInstance());

executionLog.getApplicationInstance().setLastLog(executionLog);
em.persist(executionLog);

The relevant portions of the entity beans are as follows:

public class ExecutionLog implements Serializable {

    private static final long serialVersionUID = 1L;

    @Id
    @GeneratedValue(strategy=GenerationType.IDENTITY)
    private Integer id;

    @ManyToOne
    @JoinColumn(name="application_instance_id")
    private ApplicationInstance applicationInstance;

public class ApplicationInstance implements Serializable {

    private static final long serialVersionUID = 1L;

    @Id
    @GeneratedValue(strategy=GenerationType.IDENTITY)
    private Integer id;

    @OneToOne
    @JoinColumn(name="last_log_id", nullable = true)
    private ExecutionLog lastLog;

A one-to-one relationship exists as at any point, a specific log record can only be linked to a specific application instance record.

So in essence, what I'm doing is creating log records, and then updating the application instance so it is linked to the latest log record relevant to it. This is done in a single transactional method, but failure seems to occur when the application instance record is updated. However, this works fine on a single call, but not on concurrent calls.

Hope this adds more clarity to my question.

Solution

Your shared "application instance" row pointing to the latest log entry is begging for locking problems. It seems to me that the sequence will be:

• select from application_instance
• insert into execution_log, referencing application_instance (takes shared lock on application_instance row)
• update application_instance (takes exclusive lock on application_instance row)

So two threads could both have the shared lock on application_instance; thread A then blocks on thread B trying to do the update, and then thread B blocks on thread A...

I would solve this by getting the application instance with an exclusive lock immediately. In direct Hibernate terms that would be done by specifying LockMode.UPGRADE (or LockMode.PESSIMISTIC_WRITE) when loading the entity (session.get or on the query).

(I would also re-examine if you actually need to update application_instance to point at the latest log entry each time- it is a bottleneck as all transactions need to synchronise/serialise on it.)