jBPM Spring Boot app with org.hibernate.exception.LockAcquisitionException

[Jérôme Gisson]

Hi,

In a Spring Boot application with jBPM 6.4.Final integrated (like https://github.com/mswiderski/jbpm-examples/tree/master/spring-boot-jbpm), we have an issue with database Lock:

2017-05-22 15:16:29,045 WARN  [XNIO-2 task-22] SqlExceptionHelper: SQL Error: 1205, SQLState: 40001
2017-05-22 15:16:29,045 ERROR [XNIO-2 task-22] SqlExceptionHelper: Lock wait timeout exceeded; try restarting transaction
2017-05-22 15:16:29,047 WARN  [XNIO-2 task-22] TaskTransactionInterceptor: Could not commit session
javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement
        at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1387)
        at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1310)
        at org.hibernate.ejb.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:1397)
        at org.hibernate.ejb.AbstractQueryImpl.executeUpdate(AbstractQueryImpl.java:108)
        at org.jbpm.services.task.persistence.JPATaskPersistenceContext.executeUpdateString(JPATaskPersistenceContext.java:479)
        at org.jbpm.services.task.audit.JPATaskLifeCycleEventListener.afterTaskOutputVariableChangedEvent(JPATaskLifeCycleEventListener.java:759)
        at org.jbpm.services.task.events.TaskEventSupport.fireAfterTaskOutputVariablesChanged(TaskEventSupport.java:392)
        at org.jbpm.services.task.impl.TaskContentServiceImpl.addOutputContent(TaskContentServiceImpl.java:90)
        at org.jbpm.services.task.internals.lifecycle.MVELLifeCycleManager.taskOperation(MVELLifeCycleManager.java:383)
        at org.jbpm.services.task.impl.TaskInstanceServiceImpl.complete(TaskInstanceServiceImpl.java:188)
        at org.jbpm.services.task.commands.CompleteTaskCommand.execute(CompleteTaskCommand.java:76)
        at org.jbpm.services.task.commands.CompleteTaskCommand.execute(CompleteTaskCommand.java:39)
        at org.jbpm.services.task.commands.CompositeCommand.execute(CompositeCommand.java:146)
        at org.jbpm.services.task.commands.TaskCommandExecutorImpl$SelfExecutionCommandService.execute(TaskCommandExecutorImpl.java:65)
        at org.drools.core.command.impl.AbstractInterceptor.executeNext(AbstractInterceptor.java:41)
        at org.jbpm.services.task.persistence.TaskTransactionInterceptor.execute(TaskTransactionInterceptor.java:69)
        at org.drools.core.command.impl.AbstractInterceptor.executeNext(AbstractInterceptor.java:41)
        at org.drools.persistence.jta.TransactionLockInterceptor.execute(TransactionLockInterceptor.java:73)
        at org.drools.core.command.impl.AbstractInterceptor.executeNext(AbstractInterceptor.java:41)
        at org.drools.persistence.jpa.OptimisticLockRetryInterceptor.execute(OptimisticLockRetryInterceptor.java:82)
        at org.jbpm.services.task.commands.TaskCommandExecutorImpl.execute(TaskCommandExecutorImpl.java:40)
        at org.jbpm.services.task.impl.command.CommandBasedTaskService.complete(CommandBasedTaskService.java:174)
        at org.jbpm.runtime.manager.impl.task.SynchronizedTaskService.complete(SynchronizedTaskService.java:133)
        at org.jbpm.kie.services.impl.UserTaskServiceImpl.complete(UserTaskServiceImpl.java:189)
....
        at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:802)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement
        at org.hibernate.dialect.MySQLDialect$1.convert(MySQLDialect.java:411)
        at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49)
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:125)
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:110)
        at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:136)
        at org.hibernate.hql.internal.ast.exec.BasicExecutor.execute(BasicExecutor.java:103)
        at org.hibernate.hql.internal.ast.QueryTranslatorImpl.executeUpdate(QueryTranslatorImpl.java:413)
        at org.hibernate.engine.query.spi.HQLQueryPlan.performExecuteUpdate(HQLQueryPlan.java:282)
        at org.hibernate.internal.SessionImpl.executeUpdate(SessionImpl.java:1289)
        at org.hibernate.internal.QueryImpl.executeUpdate(QueryImpl.java:116)
        at org.hibernate.ejb.QueryImpl.internalExecuteUpdate(QueryImpl.java:194)
        at org.hibernate.ejb.AbstractQueryImpl.executeUpdate(AbstractQueryImpl.java:99)
        ... 132 common frames omitted
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
        at com.mysql.jdbc.Util.getInstance(Util.java:387)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:946)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3878)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3814)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2478)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2625)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2551)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
        at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2073)
        at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2009)
        at com.mysql.jdbc.PreparedStatement.executeLargeUpdate(PreparedStatement.java:5094)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1994)
        at com.mysql.jdbc.jdbc2.optional.PreparedStatementWrapper.executeUpdate(PreparedStatementWrapper.java:724)
        at sun.reflect.GeneratedMethodAccessor186.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at bitronix.tm.resource.jdbc.BaseProxyHandlerClass.invoke(BaseProxyHandlerClass.java:64)
        at com.sun.proxy.$Proxy115.executeUpdate(Unknown Source)
        at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:133)
        ... 139 common frames omitted

The database is a MySQL server 5.6.19-0ubuntu0.14.04.1 and I connect with MySQL connector/J version 5.1.38 and Bitronix 2.1.4.

We reproduce this issue with READ-COMMITED and REPEATABLE-READ isolation level when we deploy and run multiple version of our processes.

In MySQL, I found this locks:
mysql> SELECT * FROM `information_schema`.`innodb_trx` ORDER BY `trx_started`;
+---------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+---------------------------------------------------------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
| trx_id  | trx_state | trx_started         | trx_requested_lock_id | trx_wait_started    | trx_weight | trx_mysql_thread_id | trx_query                                               | trx_operation_state | trx_tables_in_use | trx_tables_locked | trx_lock_structs | trx_lock_memory_bytes | trx_rows_locked | trx_rows_modified | trx_concurrency_tickets | trx_isolation_level | trx_unique_checks | trx_foreign_key_checks | trx_last_foreign_key_error | trx_adaptive_hash_latched | trx_adaptive_hash_timeout | trx_is_read_only | trx_autocommit_non_locking |
+---------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+---------------------------------------------------------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
| 7604055 | RUNNING   | 2017-05-22 17:02:58 | NULL                  | NULL                |         11 |                  47 | NULL                                                    | NULL                |                 0 |                 0 |                5 |                  1184 |               1 |                 6 |                       0 | READ COMMITTED      |                 1 |                      1 | NULL                       |                         0 |                      9827 |                0 |                          0 |
| 7604298 | LOCK WAIT | 2017-05-22 17:05:48 | 7604298:2198:3:157    | 2017-05-22 17:05:49 |          5 |                  49 | delete from TaskVariableImpl where type=1 and taskId=17 | fetching rows       |                 1 |                 1 |                4 |                  1184 |               1 |                 1 |                       0 | READ COMMITTED      |                 1 |                      1 | NULL                       |                         0 |                      9979 |                0 |                          0 |
| 7604320 | LOCK WAIT | 2017-05-22 17:06:22 | 7604320:2198:3:157    | 2017-05-22 17:06:22 |          5 |                  48 | delete from TaskVariableImpl where type=1 and taskId=1  | fetching rows       |                 1 |                 1 |                4 |                  1184 |               1 |                 1 |                       0 | READ COMMITTED      |                 1 |                      1 | NULL                       |                         0 |                      9915 |                0 |                          0 |
+---------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+---------------------------------------------------------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
3 rows in set (0,00 sec)
mysql> SELECT * FROM `information_schema`.`innodb_trx` ORDER BY `trx_started`;
+---------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+---------------------------------------------------------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
| trx_id  | trx_state | trx_started         | trx_requested_lock_id | trx_wait_started    | trx_weight | trx_mysql_thread_id | trx_query                                               | trx_operation_state | trx_tables_in_use | trx_tables_locked | trx_lock_structs | trx_lock_memory_bytes | trx_rows_locked | trx_rows_modified | trx_concurrency_tickets | trx_isolation_level | trx_unique_checks | trx_foreign_key_checks | trx_last_foreign_key_error | trx_adaptive_hash_latched | trx_adaptive_hash_timeout | trx_is_read_only | trx_autocommit_non_locking |
+---------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+---------------------------------------------------------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
| 7604055 | RUNNING   | 2017-05-22 17:02:58 | NULL                  | NULL                |         11 |                  47 | NULL                                                    | NULL                |                 0 |                 0 |                5 |                  1184 |               1 |                 6 |                       0 | READ COMMITTED      |                 1 |                      1 | NULL                       |                         0 |                      9827 |                0 |                          0 |
| 7604380 | LOCK WAIT | 2017-05-22 17:07:13 | 7604380:2198:3:157    | 2017-05-22 17:07:13 |          5 |                  50 | delete from TaskVariableImpl where type=1 and taskId=3  | fetching rows       |                 1 |                 1 |                4 |                  1184 |               1 |                 1 |                       0 | READ COMMITTED      |                 1 |                      1 | NULL                       |                         0 |                     10000 |                0 |                          0 |
| 7604388 | LOCK WAIT | 2017-05-22 17:07:31 | 7604388:2198:3:157    | 2017-05-22 17:07:31 |          3 |                  48 | delete from TaskVariableImpl where type=1 and taskId=19 | fetching rows       |                 1 |                 1 |                3 |                  1184 |               1 |                 0 |                       0 | READ COMMITTED      |                 1 |                      1 | NULL                       |                         0 |                      9894 |                0 |                          0 |
+---------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+---------------------------------------------------------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
3 rows in set (0,00 sec)

Do you have an idea why or how this locks occur ?

Best regards,
Jérôme.

[Maciej Swiderski]

take a look at this thread and see if creating index helps:

https://groups.google.com/forum/#!msg/jbpm-development/txHAUfLpqlA/AEGpX0gbBAAJ;context-place=forum/jbpm-development

Maciej

--
You received this message because you are subscribed to the Google Groups "jBPM Usage" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jbpm-usage+unsubscribe@googlegroups.com.
To post to this group, send email to jbpm-...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/jbpm-usage/125469d2-5fa5-4865-913e-601afb0fed33%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Jérôme Gisson]

Hi Maciej,

Thank you for your reply.

I forgot to mention this issue occur in a test environment, with less of 100 tasks. If an index helps, I suppose is not the main problem.

I have a method in a service Spring who call many methods of org.jbpm.services.api.UserTaskService and I don't declare my method with the @Transactional annotation.
  - In this case, eatch UserTaskService method use this own transaction ?
  - Can I declare my method as @Transactional to force the same transaction for all UserTaskService call ?

Example:
        @Override
    public BpmTaskDTO execute(String userId, Long taskId, TaskResponseDTO taskResponseDTO) {
        UserTaskInstanceDesc task = runtimeDataService.getTaskById(taskId);

        // start and complete task
        if (!Status.InProgress.name().equals(task.getStatus())) {
            userTaskService.start(taskId, userId);
        }
        userTaskService.complete(taskId, userId, taskResponseDTO.getVariables());

        // Try to get and claim the next user task for this process instance
        log.debug("Task {} complete, try to get and claim the next user task for this process instance {}", task.getTaskId(), task.getProcessInstanceId());
        List<Status> status = new ArrayList<>(Arrays.asList(Status.Created, Status.Ready, Status.Reserved));
        List<TaskSummary> taskSummaries = runtimeDataService.getTasksByStatusByProcessInstanceId(task.getProcessInstanceId(), status, getDefaultFilter());

        BpmTaskDTO nextUserTask = null;
        if (!taskSummaries.isEmpty()) {
            TaskSummary ts = taskSummaries.get(0);
            try {
                userTaskService.claim(ts.getId(), userId);
                log.debug("Task {} of process instance {} was claimed by {}", ts.getId(), ts.getProcessInstanceId(), userId);
                nextUserTask = convertTaskSummary(ts, true);
            } catch (PermissionDeniedException pde) {
                // No user task available for this user (can not claim any task)
            }
        }

        return nextUserTask;
    }

Regards,
Jérôme.

To unsubscribe from this group and stop receiving emails from it, send an email to jbpm-usage+...@googlegroups.com.

[Maciej Swiderski]

Jerome,

On 23 May 2017, at 10:58, Jérôme Gisson <jerome...@gmail.com> wrote:

Hi Maciej,

Thank you for your reply.

I forgot to mention this issue occur in a test environment, with less of 100 tasks. If an index helps, I suppose is not the main problem.

I have a method in a service Spring who call many methods of org.jbpm.services.api.UserTaskService and I don't declare my method with the @Transactional annotation.
  - In this case, eatch UserTaskService method use this own transaction ?

yes

  - Can I declare my method as @Transactional to force the same transaction for all UserTaskService call ?

yes, that would make more sense and should be faster

moreover, looks like you do some of the things manually that the engine can do for you - for instance getting task, checking its status and optionally start before completing it can be achieved by https://github.com/kiegroup/jbpm/blob/6.4.x/jbpm-services/jbpm-services-api/src/main/java/org/jbpm/services/api/UserTaskService.java#L72

the auto claim can be achieved by using swimlanes - user who completes the first task of the lane will be prefered user for all other tasks on that lane. Alternatively you can again use autoProgress feature that can also claim the task.

Maciej

To view this discussion on the web visit https://groups.google.com/d/msgid/jbpm-usage/cbc38842-522c-4812-8e2b-a4e024e520c0%40googlegroups.com.

[Jérôme Gisson]

The method UserTaskService.completeAutoProgress is very useful. I refactor my code to use it :)
I also add an @Transactionnal annotation on all my service method, but I have an other exception:

2017-05-23 15:42:22,976 ERROR [XNIO-2 task-3] TransactionSynchronizationUtils: TransactionSynchronization.beforeCompletion threw exception
javax.persistence.OptimisticLockException: org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.drools.persistence.info.SessionInfo#1]
    at org.hibernate.ejb.AbstractEntityManagerImpl.wrapStaleStateException(AbstractEntityManagerImpl.java:1416)
    at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1329)
    at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1310)
    at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1316)
    at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:999)
    at sun.reflect.GeneratedMethodAccessor289.invoke(Unknown Source)

    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)

    at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:347)
    at com.sun.proxy.$Proxy113.flush(Unknown Source)
    at org.drools.persistence.TriggerUpdateTransactionSynchronization.beforeCompletion(TriggerUpdateTransactionSynchronization.java:72)
    at org.kie.spring.persistence.SpringTransactionSynchronizationAdapter.beforeCompletion(SpringTransactionSynchronizationAdapter.java:54)
    at org.springframework.transaction.support.TransactionSynchronizationUtils.triggerBeforeCompletion(TransactionSynchronizationUtils.java:106)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerBeforeCompletion(AbstractPlatformTransactionManager.java:945)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:745)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:730)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:504)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:292)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655)
    at fr.tessi.datacontent.bpm.service.task.impl.BpmTaskServiceImpl$$EnhancerBySpringCGLIB$$473be5cc.getTasksOwnedByUser(<generated>)

....
    at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:802)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

Caused by: org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.drools.persistence.info.SessionInfo#1]
    at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:2509)
    at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3219)
    at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3117)
    at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3446)
    at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:140)
    at org.hibernate.engine.spi.ActionQueue.execute(ActionQueue.java:362)
    at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:354)
    at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:276)
    at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:328)
    at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:52)
    at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1233)
    at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:996)
    ... 127 common frames omitted

I deploy each version of my kmodule with a SINGLETON strategy.
  - In this case I have only a ksession for each version (regardless the number of process definitions and process instances) ?
  - Change the deployment strategy to PER_REQUEST or PER_PROCESS_INSTANCE can avoid this kind of problem ?

Jérôme.

[Maciej Swiderski]

Jerome,

correct, it is single ksession shared between all processes 

  - Change the deployment strategy to PER_REQUEST or PER_PROCESS_INSTANCE can avoid this kind of problem ?

yes, I would recommend to use per process instance

Maciej 

To unsubscribe from this group and stop receiving emails from it, send an email to jbpm-usage+unsubscribe@googlegroups.com.

To post to this group, send email to jbpm-...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/jbpm-usage/1842dc84-6ff0-44c4-905b-6e09c14219bd%40googlegroups.com.

[Jérôme Gisson]

Hi,

 

I change my deployment strategy to per process instance and it solve my concurrence issue.

The application is more stable now, and there is no freeze when the load increase.

 

Many thanks for your help.

 

Jérôme.

Jerome,