Conductor: v1.10.0 BACKEND_ERROR - Deadlock found when trying to get lock; try restarting transaction

[juaby]

com.netflix.conductor.core.execution.ApplicationException: BACKEND_ERROR - Deadlock found when trying to get lock; try restarting transaction
at com.netflix.conductor.dao.mysql.MySQLBaseDAO.getWithTransaction(MySQLBaseDAO.java:103)
at com.netflix.conductor.dao.mysql.MySQLBaseDAO.withTransaction(MySQLBaseDAO.java:125)
at com.netflix.conductor.dao.mysql.MySQLExecutionDAO.updateLastPoll(MySQLExecutionDAO.java:451)
at com.netflix.conductor.service.ExecutionService.poll(ExecutionService.java:133)
at com.netflix.conductor.server.resources.TaskResource.batchPoll(TaskResource.java:115)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)
at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1542)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1473)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1419)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1409)
at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:409)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:558)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:733)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at com.google.inject.servlet.ServletDefinition.doServiceImpl(ServletDefinition.java:286)
at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:276)
at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:181)
at com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:91)
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:85)
at com.netflix.conductor.server.JerseyModule$1.doFilter(JerseyModule.java:97)
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
at com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:120)
at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:135)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1676)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:581)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1174)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1106)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
at org.eclipse.jetty.server.Server.handle(Server.java:524)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:319)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:253)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589)
at java.lang.Thread.run(Thread.java:748)
Caused by: com.netflix.conductor.core.execution.ApplicationException: Deadlock found when trying to get lock; try restarting transaction
at com.netflix.conductor.dao.mysql.Query.executeUpdate(Query.java:274)
at com.netflix.conductor.dao.mysql.MySQLExecutionDAO.lambda$insertOrUpdatePollData$56(MySQLExecutionDAO.java:812)
at com.netflix.conductor.dao.mysql.MySQLBaseDAO.execute(MySQLBaseDAO.java:170)
at com.netflix.conductor.dao.mysql.MySQLExecutionDAO.insertOrUpdatePollData(MySQLExecutionDAO.java:808)
at com.netflix.conductor.dao.mysql.MySQLExecutionDAO.lambda$updateLastPoll$25(MySQLExecutionDAO.java:451)
at com.netflix.conductor.dao.mysql.MySQLBaseDAO.lambda$withTransaction$3(MySQLBaseDAO.java:126)
at com.netflix.conductor.dao.mysql.MySQLBaseDAO.getWithTransaction(MySQLBaseDAO.java:98)
... 52 more

[robertofabrizi]

Same here

[jvemugunta]

I am able to replicate the error.

1) Stop the conductor server
2) Start the clientWorker so that the worker polls indefinitely

Here is my worker code

public class DomainClient {

    public static void main(String[] args) {

       System.setProperty("conductor.worker.T1.domain", "mydomain");

        TaskClient taskClient = new TaskClient();
        taskClient.setRootURI("http://localhost:8080/api/");

        int threadCount = 4;
        Worker worker1 = new DomainWorker("T1");
        Worker worker2 = new DomainWorker("T1");
        Worker worker3 = new DomainWorker("T1");

        WorkflowTaskCoordinator.Builder builder = new WorkflowTaskCoordinator.Builder();
        WorkflowTaskCoordinator coordinator = builder.withWorkers(worker1,worker2,worker3).withThreadCount(threadCount)
                .withTaskClient(taskClient).build();

        // Start for polling and execution of the tasks
        coordinator.init();

    }

Drop and create the existing conductor database as

3) drop database conductor;
4) create database conductor;

Now, Start the conductor server, you will see the above error. It looks like when mutiple threads are trying to call the below method. deadlock is created

public void updateLastPoll(String taskDefName, String domain, String workerId) {
        Preconditions.checkNotNull(taskDefName, "taskDefName name cannot be null");
        PollData pollData = new PollData(taskDefName, domain, workerId, System.currentTimeMillis());
        String effectiveDomain = (domain == null) ? "DEFAULT" : domain;
        withTransaction(tx -> insertOrUpdatePollData(tx, pollData, effectiveDomain));
}

[jvemugunta]

I am able to replicate the deadlock issue at will

This issue happens when multiple threads are polling for the same task.
The below code does both update and insert on the same row and with multiple threads the deadlock will occur. I don't know how to fix it

https://github.com/Netflix/conductor/blob/39a851fcf7cfe807f6288a39f08c455eb165ce11/mysql-persistence/src/main/java/com/netflix/conductor/dao/mysql/MySQLExecutionDAO.java#L795-L814

[jvemugunta]

I have captured the lock history. Is there anyone who can help with this issue?

*** (1) TRANSACTION:
TRANSACTION 1349140, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 360, 2 row lock(s), undo log entries 1
MySQL thread id 5210, OS thread handle 0x700006e5e000, query id 2213514 localhost 127.0.0.1 root update
INSERT INTO poll_data (queue_name, domain, json_data) VALUES ('T1', 'mydomain', '{"queueName":"T1","domain":"mydomain","workerId":"Jagadish","lastPollTime":1529641117215}')
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 882 page no 4 n bits 72 index `unique_poll_data` of table `conductor`.`poll_data` trx id 1349140 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

*** (2) TRANSACTION:
TRANSACTION 1349138, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
3 lock struct(s), heap size 360, 2 row lock(s), undo log entries 1
MySQL thread id 5211, OS thread handle 0x700006622000, query id 2213512 localhost 127.0.0.1 root update
INSERT INTO poll_data (queue_name, domain, json_data) VALUES ('T1', 'mydomain', '{"queueName":"T1","domain":"mydomain","workerId":"Jagadish","lastPollTime":1529641117215}')
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 882 page no 4 n bits 72 index `unique_poll_data` of table `conductor`.`poll_data` trx id 1349138 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 882 page no 4 n bits 72 index `unique_poll_data` of table `conductor`.`poll_data` trx id 1349138 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

*** WE ROLL BACK TRANSACTION (2)

[jvemugunta]

@juaby and @robertofabrizi
I have fixed the issue. Recreated the problem and offered the fix in the pull request. Let me know what you think

https://github.com/Netflix/conductor/pull/621

[mashurex]

@jvemugunta Thanks for tackling this. When I submitted a PR to migrate the MySQL module from using a niche ORM (Sql2o) to vanilla JDBC I mostly left existing queries and patterns in place to make it easier to debug and do side by side comparisons of the new code vs. the old code. Some of those patterns, like the one above, attempt to update optimistically and then insert if nothing was there. I believe this is in a few more DAO methods throughout the entire MySQL module.

In lieu of a synchronized block (or possibly, in conjunction with a synchronized block), I wonder if it'd be more performant to use a REPLACE statement instead of an UPDATE then fallback to INSERT.

Something like:

REPLACE INTO poll_data (
  queue_name, 
  domain, 
  json_data, 
  modified_on
) VALUES (?, ?, ?, CURRENT_TIMESTAMP)

I'm writing that from memory, so it may be off, but if it works I would imagine it to be quicker than UPDATE then INSERT because that's two round trips to the database.

If REPLACE has issues, a regular ol' upsert might do the trick as well...

INSERT INTO poll_data (
  queue_name, 
  domain, 
  json_data, 
  modified_on
) VALUES (?, ?, ?, CURRENT_TIMESTAMP)
ON DUPLICATE KEY UPDATE
  json_data = ?
  modified_on = CURRENT_TIMESTAMP

What do you think?

[jvemugunta]

This is an excellent idea. I will try this one

INSERT INTO poll_data ( queue_name, domain, json_data, modified_on ) VALUES (?, ?, ?, CURRENT_TIMESTAMP) ON DUPLICATE KEY UPDATE json_data = ? modified_on = CURRENT_TIMESTAMP

[jvemugunta]

@mashurex

I have updated the PR. Please review and let me know your feedback.
https://github.com/Netflix/conductor/pull/621

Please review the fix and let me know what you think. There are other places that requires changes.
I will fix them too once this PR is approved. We need to fix all of these methods. I will do load test with 100 concurrent threads to see any potential race or deadlocks in MYSQL module.

BTW, I like Sql2o approach. It is simple and precise. Thanks for the tip

[jvemugunta]

The issue has been fixed and the code has been merged into the dev branch
https://github.com/Netflix/conductor/pull/621

@juaby . You can now close the issue.