Deadlock with Event Registry - Microsoft sqlserver

Flowable Engine
1

We have a case model that uses about 15 event registry Rabbit listeners. I appears one of the events got caught up in a deadlock. The case expired few hours later due to a overall case expiration timer.

Kinda looking for some traction on how/what causes the deadlock. We have had several good runs of the case model in the past with all events getting process and the case exiting gracefully.

org.apache.ibatis.exceptions.PersistenceException:

### Error updating database. Cause: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 207) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.

### The error may exist in org/flowable/cmmn/db/mapping/entity/PlanItemInstance.xml

### The error may involve org.flowable.cmmn.engine.impl.persistence.entity.PlanItemInstanceEntityImpl.updatePlanItemInstance-Inline

### The error occurred while setting parameters

### SQL: update ACT_CMMN_RU_PLAN_ITEM_INST SET REV_ = ?, STATE_ = ?, OCCURRED_TIME_ = ?, ENDED_TIME_ = ?, IS_COMPLETEABLE_ = ? where ID_ = ? and REV_ = ?

### Cause: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 207) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.

at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30) ~[mybatis-3.5.3.jar!/:3.5.3]

at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:199) ~[mybatis-3.5.3.jar!/:3.5.3]

at org.flowable.common.engine.impl.db.DbSqlSession.flushUpdates(DbSqlSession.java:570) ~[flowable-engine-common-6.5.0.jar!/:6.5.0]

at org.flowable.common.engine.impl.db.DbSqlSession.flush(DbSqlSession.java:359) ~[flowable-engine-common-6.5.0.jar!/:6.5.0]

at org.flowable.common.engine.impl.interceptor.CommandContext.flushSessions(CommandContext.java:192) ~[flowable-engine-common-6.5.0.jar!/:6.5.0]

at org.flowable.common.engine.impl.interceptor.CommandContext.close(CommandContext.java:61) ~[flowable-engine-common-6.5.0.jar!/:6.5.0]

at org.flowable.common.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:81) ~[flowable-engine-common-6.5.0.jar!/:6.5.0]

at org.flowable.common.spring.SpringTransactionInterceptor.lambda$execute$0(SpringTransactionInterceptor.java:56) ~[flowable-spring-common-6.5.0.jar!/:6.5.0]

at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140) ~[spring-tx-5.2.4.RELEASE.jar!/:5.2.4.RELEASE]

at org.flowable.common.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:56) ~[flowable-spring-common-6.5.0.jar!/:6.5.0]

at org.flowable.common.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:30) ~[flowable-engine-common-6.5.0.jar!/:6.5.0]

at org.flowable.common.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:56) ~[flowable-engine-common-6.5.0.jar!/:6.5.0]

at org.flowable.common.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:51) ~[flowable-engine-common-6.5.0.jar!/:6.5.0]

at org.flowable.cmmn.engine.impl.runtime.PlanItemInstanceTransitionBuilderImpl.trigger(PlanItemInstanceTransitionBuilderImpl.java:129) ~[flowable-cmmn-engine-6.5.0.jar!/:6.5.0]

at org.flowable.cmmn.engine.impl.eventregistry.CmmnEventRegistryEventConsumer.handleEventSubscription(CmmnEventRegistryEventConsumer.java:84) ~[flowable-cmmn-engine-6.5.0.jar!/:6.5.0]

at org.flowable.cmmn.engine.impl.eventregistry.CmmnEventRegistryEventConsumer.eventReceived(CmmnEventRegistryEventConsumer.java:70) ~[flowable-cmmn-engine-6.5.0.jar!/:6.5.0]

at org.flowable.eventregistry.impl.consumer.BaseEventRegistryEventConsumer.eventReceived(BaseEventRegistryEventConsumer.java:57) ~[flowable-event-registry-6.5.0.jar!/:6.5.0]

at org.flowable.eventregistry.impl.DefaultEventRegistry.sendEventToConsumers(DefaultEventRegistry.java:63) ~[flowable-event-registry-6.5.0.jar!/:6.5.0]

at org.flowable.eventregistry.impl.DefaultInboundEventProcessor.eventReceived(DefaultInboundEventProcessor.java:42) ~[flowable-event-registry-6.5.0.jar!/:6.5.0]

at org.flowable.eventregistry.impl.DefaultEventRegistry.eventReceived(DefaultEventRegistry.java:56) ~[flowable-event-registry-6.5.0.jar!/:6.5.0]

at org.flowable.eventregistry.api.EventRegistry$eventReceived.call(Unknown Source) ~[na:na]

at com.m.gpa.workflow.event.registry.EssChannelMessageListenerAdapter.onMessage(EssChannelMessageListenerAdapter.groovy:49) ~[flowable-event-registry-starter-1.3-SNAPSHOT.jar!/:1.3-SNAPSHOT]

at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerContainer.java:1635) ~[spring-rabbit-2.2.5.RELEASE.jar!/:2.2.5.RELEASE]

at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.actualInvokeListener(AbstractMessageListenerContainer.java:1509) ~[spring-rabbit-2.2.5.RELEASE.jar!/:2.2.5.RELEASE]

at jdk.internal.reflect.GeneratedMethodAccessor436.invoke(Unknown Source) ~[na:na]

at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:na]

at java.base/java.lang.reflect.Method.invoke(Unknown Source) ~[na:na]

at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344) ~[spring-aop-5.2.4.RELEASE.jar!/:5.2.4.RELEASE]

at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198) ~[spring-aop-5.2.4.RELEASE.jar!/:5.2.4.RELEASE]

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.2.4.RELEASE.jar!/:5.2.4.RELEASE]

at brave.spring.rabbit.TracingRabbitListenerAdvice.invoke(TracingRabbitListenerAdvice.java:101) ~[brave-instrumentation-spring-rabbit-5.10.1.jar!/:na]

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.4.RELEASE.jar!/:5.2.4.RELEASE]

at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.2.4.RELEASE.jar!/:5.2.4.RELEASE]

at org.springframework.amqp.rabbit.listener.$Proxy265.invokeListener(Unknown Source) ~[na:2.2.5.RELEASE]

at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.invokeListener(AbstractMessageListenerContainer.java:1486) ~[spring-rabbit-2.2.5.RELEASE.jar!/:2.2.5.RELEASE]

at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.doExecuteListener(AbstractMessageListenerContainer.java:1477) ~[spring-rabbit-2.2.5.RELEASE.jar!/:2.2.5.RELEASE]

at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.executeListener(AbstractMessageListenerContainer.java:1421) ~[spring-rabbit-2.2.5.RELEASE.jar!/:2.2.5.RELEASE]

at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.doReceiveAndExecute(SimpleMessageListenerContainer.java:963) ~[spring-rabbit-2.2.5.RELEASE.jar!/:2.2.5.RELEASE]

at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.receiveAndExecute(SimpleMessageListenerContainer.java:913) ~[spring-rabbit-2.2.5.RELEASE.jar!/:2.2.5.RELEASE]

at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.access$1600(SimpleMessageListenerContainer.java:81) ~[spring-rabbit-2.2.5.RELEASE.jar!/:2.2.5.RELEASE]

at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.mainLoop(SimpleMessageListenerContainer.java:1284) ~[spring-rabbit-2.2.5.RELEASE.jar!/:2.2.5.RELEASE]

at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.run(SimpleMessageListenerContainer.java:1190) ~[spring-rabbit-2.2.5.RELEASE.jar!/:2.2.5.RELEASE]

at java.base/java.lang.Thread.run(Unknown Source) ~[na:na]

Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 207) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.

at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDatabaseError(SQLServerException.java:262) ~[mssql-jdbc-8.2.2.jre11.jar!/:na]

at com.microsoft.sqlserver.jdbc.SQLServerStatement.getNextResult(SQLServerStatement.java:1632) ~[mssql-jdbc-8.2.2.jre11.jar!/:na]

at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatement(SQLServerPreparedStatement.java:600) ~[mssql-jdbc-8.2.2.jre11.jar!/:na]

at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.doExecute(SQLServerPreparedStatement.java:522) ~[mssql-jdbc-8.2.2.jre11.jar!/:na]

at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7225) ~[mssql-jdbc-8.2.2.jre11.jar!/:na]

at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:3053) ~[mssql-jdbc-8.2.2.jre11.jar!/:na]

at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(SQLServerStatement.java:247) ~[mssql-jdbc-8.2.2.jre11.jar!/:na]

at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:222) ~[mssql-jdbc-8.2.2.jre11.jar!/:na]

at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.execute(SQLServerPreparedStatement.java:503) ~[mssql-jdbc-8.2.2.jre11.jar!/:na]

at com.zaxxer.hikari.pool.ProxyPreparedStatement.execute(ProxyPreparedStatement.java:44) ~[HikariCP-3.4.2.jar!/:na]

at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute(HikariProxyPreparedStatement.java) ~[HikariCP-3.4.2.jar!/:na]

at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:47) ~[mybatis-3.5.3.jar!/:3.5.3]

at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:74) ~[mybatis-3.5.3.jar!/:3.5.3]

at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:50) ~[mybatis-3.5.3.jar!/:3.5.3]

at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:117) ~[mybatis-3.5.3.jar!/:3.5.3]

at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:76) ~[mybatis-3.5.3.jar!/:3.5.3]

at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:197) ~[mybatis-3.5.3.jar!/:3.5.3]

... 41 common frames omitted

2

@joram @tijs
Any clue on this? I hesitate to share CMMN, so how can I progress?

3

Hey @tjmac,

Can you share the number of messages that you are receiving over Rabbit?

Is it possible for you to get the xml_deadlock_report from SQL Server? I’ve found this blog post talking about how to get that.

On a side note, see in the stacktrace that you are using your own EssChannelMessageListenerAdapter is this a replacement of the Flowable one? Are you using channels or you are using @RabbitListener from Spring? If you are using the Flowable channels, will you be willing to share with us what was missing in the out of the configuration that you needed to add your own? Asking because we want to improve on this to make it easier for users to use this functionality.

Cheers,
Filip

4

The side note of EssChannelMessageListenerAdapter extension was to get the Rabbit message headers so they could be used for correlation.

5

So the dba is suggesting that there is some discrepancy on how table is defined vs how the update parameters is called. For instance in picture below the varchar in the parameter is going to be cast to nvchar. The implicit cast and negates the use of the index/PK and results in a table scan/table lock

image
image1051×667 81.2 KB

6

Volume can be many per second. The same event with same correlation can happen many times per second (5 per second). This is in a 2 instance cluster.

Running this locally, one instance, and giving it a very heavy load, the probably is not seen.

7

The reference in the following post to the Camunda documentation, alter table, fixed these deadlock issues: