Prisma1: Deadlock found when trying to get lock; try restarting transaction

[marktani]

Bug Report

Current behavior

Running nested mutations in quick succession results in an internal server error, and this cluster log:

prisma-database_1  | java.sql.SQLTransactionRollbackException: (conn=164) Deadlock found when trying to get lock; try restarting transaction
prisma-database_1  |    at org.mariadb.jdbc.internal.util.exceptions.ExceptionMapper.get(ExceptionMapper.java:165)
prisma-database_1  |    at org.mariadb.jdbc.internal.util.exceptions.ExceptionMapper.getException(ExceptionMapper.java:106)
prisma-database_1  |    at org.mariadb.jdbc.MariaDbStatement.executeExceptionEpilogue(MariaDbStatement.java:235)
prisma-database_1  |    at org.mariadb.jdbc.MariaDbPreparedStatementClient.executeInternal(MariaDbPreparedStatementClient.java:224)
prisma-database_1  |    at org.mariadb.jdbc.MariaDbPreparedStatementClient.execute(MariaDbPreparedStatementClient.java:159)
prisma-database_1  |    at com.zaxxer.hikari.pool.ProxyPreparedStatement.execute(ProxyPreparedStatement.java:44)
prisma-database_1  |    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute(HikariProxyPreparedStatement.java)
prisma-database_1  |    at slick.jdbc.StatementInvoker.results(StatementInvoker.scala:39)
prisma-database_1  |    at slick.jdbc.StatementInvoker.iteratorTo(StatementInvoker.scala:22)
prisma-database_1  |    at slick.jdbc.Invoker.first(Invoker.scala:31)
prisma-database_1  |    at slick.jdbc.Invoker.first$(Invoker.scala:30)
prisma-database_1  |    at slick.jdbc.StatementInvoker.first(StatementInvoker.scala:16)
prisma-database_1  |    at slick.jdbc.StreamingInvokerAction$HeadAction.run(StreamingInvokerAction.scala:52)
prisma-database_1  |    at slick.jdbc.StreamingInvokerAction$HeadAction.run(StreamingInvokerAction.scala:51)
prisma-database_1  |    at slick.dbio.DBIOAction$$anon$4.$anonfun$run$3(DBIOAction.scala:240)
prisma-database_1  |    at scala.collection.Iterator.foreach(Iterator.scala:929)prisma-database_1  |    at scala.collection.Iterator.foreach$(Iterator.scala:929)
prisma-database_1  |    at scala.collection.AbstractIterator.foreach(Iterator.scala:1417)
prisma-database_1  |    at scala.collection.IterableLike.foreach(IterableLike.scala:71)
prisma-database_1  |    at scala.collection.IterableLike.foreach$(IterableLike.scala:70)
prisma-database_1  |    at scala.collection.AbstractIterable.foreach(Iterable.scala:54)
prisma-database_1  |    at slick.dbio.DBIOAction$$anon$4.run(DBIOAction.scala:240)
prisma-database_1  |    at slick.dbio.DBIOAction$$anon$4.run(DBIOAction.scala:238)
prisma-database_1  |    at slick.dbio.DBIOAction$$anon$4.$anonfun$run$3(DBIOAction.scala:240)
prisma-database_1  |    at scala.collection.Iterator.foreach(Iterator.scala:929)prisma-database_1  |    at scala.collection.Iterator.foreach$(Iterator.scala:929)
prisma-database_1  |    at scala.collection.AbstractIterator.foreach(Iterator.scala:1417)
prisma-database_1  |    at scala.collection.IterableLike.foreach(IterableLike.scala:71)
prisma-database_1  |    at scala.collection.IterableLike.foreach$(IterableLike.scala:70)
prisma-database_1  |    at scala.collection.AbstractIterable.foreach(Iterable.scala:54)
prisma-database_1  |    at slick.dbio.DBIOAction$$anon$4.run(DBIOAction.scala:240)
prisma-database_1  |    at slick.dbio.DBIOAction$$anon$4.run(DBIOAction.scala:238)
prisma-database_1  |    at slick.dbio.SynchronousDatabaseAction$FusedAndThenAction.$anonfun$run$4(DBIOAction.scala:534)
prisma-database_1  |    at slick.dbio.SynchronousDatabaseAction$FusedAndThenAction.$anonfun$run$4$adapted(DBIOAction.scala:534)
prisma-database_1  |    at scala.collection.Iterator.foreach(Iterator.scala:929)prisma-database_1  |    at scala.collection.Iterator.foreach$(Iterator.scala:929)
prisma-database_1  |    at scala.collection.AbstractIterator.foreach(Iterator.scala:1417)
prisma-database_1  | {"@timestamp":"2018-01-31T22:08:50.089+00:00","@version":1,"message":"{\"key\":\"request/new\",\"requestId\":\"api:api:cjd3mj44p0ati0120jbq
4k8xf\"}","logger_name":"com.prisma.api.server.ApiServer","thread_name":"single-server-akka.actor.default-dispatcher-4","level":"INFO","level_value":20000,"HOST
NAME":"95d5b2fb32e2"}
prisma-database_1  |    at scala.collection.IterableLike.foreach(IterableLike.scala:71)
prisma-database_1  |    at scala.collection.IterableLike.foreach$(IterableLike.scala:70)
prisma-database_1  |    at scala.collection.AbstractIterable.foreach(Iterable.scala:54)
prisma-database_1  |    at slick.dbio.SynchronousDatabaseAction$FusedAndThenAction.run(DBIOAction.scala:534)
prisma-database_1  |    at slick.dbio.SynchronousDatabaseAction$$anon$11.run(DBIOAction.scala:571)
prisma-database_1  |    at slick.basic.BasicBackend$DatabaseDef$$anon$2.liftedTree1$1(BasicBackend.scala:240)
prisma-database_1  |    at slick.basic.BasicBackend$DatabaseDef$$anon$2.run(BasicBackend.scala:240)
prisma-database_1  |    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
prisma-database_1  |    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
prisma-database_1  |    at java.lang.Thread.run(Thread.java:748)
prisma-database_1  | Caused by: java.sql.SQLException: Deadlock found when trying to get lock; try restarting transaction
prisma-database_1  | Query is: insert into `benchmark@dev`.`_ArticleToSource` (`id`, `A`, `B`)
prisma-database_1  |            Select 'cjd3mj44b0atf012047wa8gjf', (select id from `benchmark@dev`.`Article` where `id` = ?), `id`
prisma-database_1  |            FROM `benchmark@dev`.`Source` where `slug` = ? on duplicate key update `benchmark@dev`.`_ArticleToSource`.id=`benchmark@dev`.`_A
rticleToSource`.id, parameters ['cjd3mj44a0ata0120dwlzt1n2','test']
prisma-database_1  |    at org.mariadb.jdbc.internal.util.LogQueryTool.exceptionWithQuery(LogQueryTool.java:146)
prisma-database_1  |    at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:217)
prisma-database_1  |    at org.mariadb.jdbc.MariaDbPreparedStatementClient.executeInternal(MariaDbPreparedStatementClient.java:218)
prisma-database_1  |    ... 43 more

Reproduction

I prepared a reproduction with an older version here: https://github.com/marktani/import-testing

Expected behavior?

The deadlock does not occur, or when a deadlock occurs, the transaction is being retried for a fixed number of times.

[LawJolla]

@marktani

I made a repo that may help in testing.

https://github.com/LawJolla/prisma-concurrency-test

mutation {
  testPrismaLoad(posts: 10, concurrency: 1)
}

concurrency is how many posts are allowed "in flight" at once. 1 = sequential. The higher the numbers, the more fun!

https://cl.ly/2Q030r0k381r

[k00k]

👍 This is currently a pretty big blocker for us as we're trying to do some "batch" mutations for a big data migration.

[k00k]

Our workaround has been to console.log out all of the mutation strings and then paste them as one multi-mutation mutation in the playground like:

```
mutation {
m001: createFoo(data:{bar:1}){id}
m002: createFoo(data:{bar:1}){id}
m003: createFoo(data:{bar:1}){id}
m004: createFoo(data:{bar:1}){id}
...
}

[horsejockey]

Seeing this same issue. My mutations is like this:

mutation {
  createFoo(
    name: "something",
    r1: {
      connect: {
        id: "someid"
      }
    },
    r2: {
      connect: {
        id: "someid"
      }
    }
  )
}

Causes (conn=367) Deadlock found when trying to get lock; try restarting transaction
Happens in local cluster and deployed cluster.

[cameronk]

Seeing this as well when running several nested mutations in succession. I wrote a batching script that executed 3 nested create mutations every 500ms, but this breaks down (with the above error) after 5-7 requests.

[oguzgelal]

I've been reproducing this issue with update / create mutations, but not with upsert. However I can't also use upsert either because connect won't work under upsert (https://github.com/graphcool/prisma/issues/1579#issuecomment-360267833).

So as a workaround, I'm running the requests serially. Nowhere close to ideal.. hope this gets fixed soon.

handleOrder = (ctx, { ..., order }) =>
  new Promise(async (resolve) => {
    await ...stuff...
    resolve()
  })

handleOrders = async (ctx, { ..., orders }) => {
  await orders.reduce(
    (p, order) => p.then(_ => handleOrder(ctx, { ..., order })),
    Promise.resolve()
  )
}

module.exports = async (parent, { ..., orders }, ctx, info) => {
  ...
  await handleOrders(ctx, { ..., orders })
  ...
}

[raeesaa]

@marktani Any updates on this?

[fcosrno]

Seeing this too. I got around the issue by delaying the requests using the rxjs concat operator in my front end (Angular). Ideally I would like to be using zip instead; faster since it wouldn't be waiting for a request to finish before starting the next.

const observables = [];

// Each row is an observable request
this.rows.forEach(row => {
    observables.push(
    this.apollo.mutate({
        mutation: CreateRow,
        variables: { ...row }
    })
    );
});

Observable.concat(...observables).subscribe(
    response => {
    console.log(response);
    },
    error => {
    console.log(error);
    }
);

[lionstone]

Having the same issue

prisma-database_1 | Caused by: java.sql.SQLException: Deadlock found when trying to get lock; try restarting transaction prisma-database_1 | Query is: insert into `prisma-airbnb-example@dev`.`_UserInvitationSent` (`id`, `A`, `B`) Select 'cjf1al37j02050797etcqygyu', (SELECT `id` FROM (SELECT * FROM `prisma-airbnb-example@dev`.`Invitation`) IDFROMWHERE WHERE `id` = ?) , `id` FROM `prisma-airbnb-example@dev`.`User` where `id` = ? on duplicate key update `prisma-airbnb-example@dev`.`_UserInvitationSent`.id = `prisma-airbnb-example@dev`.`_UserInvitationSent`.id, parameters ['cjf1al37f020107977czzcu67','cjex5uaoo013z0797b1noyecm']

[skovhus]

Seems like a rather critical bug... @marktani @nikolasburk any idea what is causing this? Or suggested workarounds?

[skovhus]

Note: I could not reproduce this issue in my codebase using [email protected], but 1.3.5 and 1.4.1 fails.

[horsejockey]

It seems like I am seeing this more in 1.5.1. @marktani is there an active branch in the repo working on this bug we could follow along with? I wish I could contribute more to this fixing this issue but I am clueless. It is killing us in production right now.

[skovhus]

@sorenbs thanks for fixing this. @marktani when do you plan to release this?

[marktani]

Hey @skovhus 👋

At the latest, we will release this in 1.6.0 which is scheduled for next Tuesday. Potentially we will release 1.5.4. before then 🙂

For every commit, a new release is cut on the unstable channel. In a few minutes you should be able to upgrade your local and self-hosted cluster using the prisma@beta CLI. This process is further described in the README.

If you do so, it would be great to share your experience - whether you can confirm that all works now, or you are still experiencing any problems.

Thanks a lot!

[horsejockey]

@marktani I have been testing the beta channel.

1.5.2 pushed through 4500 nested mutations in about 30s with an error rate of about 80% deadlocking.
1.6-beta-3 I ran the same test with all 4500 requests succeeding.

[FredyC]

Looks like there is some regression in 1.8, I am getting a bunch of deadlock errors when running several mutations in parallel. Some are nested, but that's minority.

[sorenbs]

Thanks Freddy! We are working on benchmarking infrastructure that will enable us to catch regressions like this in CI. We have worked on improvements that will be released in 1.10. Would you be able to perform a test on the alpha channel to see if they improve the situation for you? https://www.prisma.io/docs/reference/prisma-servers-and-dbs/prisma-servers/overview-eu2ood0she#channels If not - could you provide one or more mutations that exhibit this behavior?

cc @do4gr

[FredyC]

@sorenbs Looks like that main culprit is indeed a nested mutation, although rather a simple one. I am usually running this query twice in parallel. Is that actually supported or do I need run in series? However, I can imagine that in a production there will be many more and those will essentially be running in parallel as well without me being able to prevent that (nor that I would want to).

mutation ($_data: PlayerUpdateInput!, $_where: PlayerWhereUniqueInput!) {
  updatePlayer(data: $_data, where: $_where) {
    id
    createdAt
    updatedAt
    name
    status
    statusExpireAt
  }
}
variables:
{
  "_data": {
    "status": "Defending",
    "statusExpireAt": "2018-06-05T05:48:12.431Z",
    "statusPlayer": {
      "connect": {
        "id": "cjhz4t5l1009g07772hcf556e"
      }
    }
  },
  "_where": {
    "id": "cjhz4ndx200910777d9nax3ed"
  }
}

Here is datamodel to be clear.

type Player {
  id: ID! @unique
  createdAt: DateTime!
  updatedAt: DateTime!
  name: String! @unique
  status: PlayerStatus! @default(value: Idle)
  statusExpireAt: DateTime
  statusPlayer: Player
}

Edit: I will try alpha channel later in this week.

[sorenbs]

@FredyC - Thanks!

Running mutations in parallel is absolutely supported and any issues that limit concurrency are treated as bugs to be fixed. Looking forward to the results of your test with alpha.

[FredyC]

@sorenbs So I have tried 1.11-alpha and unfortunately it has its own issues ...

You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '"updatedAt" = '2018-06-07 20:04:12.547' WHERE id = 'cji4yzfjr004d0728ll65rw30' at line 1
Query is: UPDATE [e-mail] SET status = ? , statusExpireAt = ? , "updatedAt" = ? WHERE id = ?, parameters ['Idle',,'2018-06-07 20:04:12.547','cji4yzfjr004d0728ll65rw30']

My knowledge of SQL is rather dusty so I am not entirely sure why would this be wrong. Either way, I am using the same MySQL container, just started secondary prisma container with alpha version on a different port and then prisma deploy there with a different service name to ensure a clean slate. Is it possible that MySQL schema is wrong and I need to separate that as well?

[marktani]

Please create a new issue for this error and include the mutation or query you are running :)

[do4gr]

@FredyC that is an issue with quoting. The updatedAt should be enclosed by ticks instead of double quotes. Apparently we give our MySql more lenient settings upon startup that's why it didn't fail in CI. I've adjusted that as well so we'll hopefully catch that in CI in the future. We'll merge a fix into alpha soon. Edit: The updateAt issue should now be fixed on alpha and beta.

[FredyC]

I have actually switched to Postgres because of this issue and so far it feels to be holding together much better with that alpha version. Need to do more thorough tests soon.

[Siyfion]

I too am also now suffering with this issue, so I feel like the fix for nested mutations in an upset has broken something to do with this fix...? Do we have a new issue to keep track of this yet @FredyC @sorenbs @marktani ?

[nickluger]

There is a regression in 1.13, it seems.
This code:

      createResultPromises.push(
        db.mutation.createResult(
          {
            data: {
              // some data ...
            }
          },
          "{ id }"
        )
      );
    }
  }
  return Promise.all(createResultPromises);

leads to:

key":"error/unhandled","
requestId":"local:api:cjk9y86g504kh0764f6wl6z79","
clientId":"default@default","
payload":{
  "exception":"java.sql.BatchUpdateException: (conn=15) Deadlock found when trying to get lock; try restarting transaction",
  "query":"mutation ($_v0_data: ResultCreateInput!) {\n  createResult(data: $_v0_data) {\n    id\n  }\n}\n","variables":"{\"_v0_data\":{\"position\":1,\"score\":9,\"satisfiedPreferences\":{\"set\":[\"prefC\",\"prefF\"]},\"item\":{\"connect\":{\"id\":\"cjk9y83qp04dd0764q0k83sb8\"}},\"run\":{\"connect\":{\"id\":\"cjk9y85nx04hv0764dlbvvk8j\"}}}}",

Worked perfectly fine in 1.10, the version we were using previously.

[mavilein]

@Siyfion : Do you have more insights for us? What version of Prisma are you running? Which connector? What's the mutation that is causing trouble for you?

@nickluger : I could reproduce your issue. It's related to the scalar list value you are setting for the field satisfiedPreferences. I am working on a fix now.

[Siyfion]

It's this set of queries, that runs over about 30 iterations.

// create venues
  const zones = await db.query.zones()
  const venueNames = ['Kricket', 'The Maze', 'Big Easy', 'The Coffee House']

  const venuePromises = zones.map(zone => {
    return db.mutation.createVenue({
      data: {
        name: `${zone.name}: ${
          venueNames[Math.floor(Math.random() * venueNames.length)]
        }`,
        shortDescription: 'An office with a few bags of crisps',
        longDescription:
          "Not exactly fine-dining. You'll be lucky to get a packet of crisps and a coke.",
        longitude: -0.13517969999998058,
        latitude: 51.51084410000001,
        addressLine1: '113–116 Bute Street',
        addressLine2: 'Cardiff Bay',
        addressCity: 'Cardiff',
        postcode: 'CF10 5EQ',
        contactNumber: '[phone]',
        instagramHandle: 'prisma',
        bookingUrl: 'https://www.opentable.com/maze-kitchen-table',
        bookingType: 'OpenTable',
        wifiSSID: 'Kanso5',
        wifiPassword: 'Nope!',
        published: false,
        zone: {
          connect: {
            id: zone.id
          }
        },
        openingHours: {
          create: {
            monday: '09:00 - 22:00',
            tuesday: '09:00 - 22:00',
            wednesday: '09:00 - 22:00',
            thursday: '09:00 - 22:00',
            friday: '09:00 - 22:00',
            saturday: '09:00 - 22:00',
            sunday: '09:00 - 22:00'
          }
        },
        imageUrls: {
          set: ['https://assets.imgix.net/unsplash/citystreet.jpg']
        },
        tags: {
          connect: [
            {
              id: breakfastTag.id
            },
            {
              id: lunchTag.id
            },
            {
              id: dinnerTag.id
            },
            {
              id: coffeeTag.id
            }
          ]
        }
      }
    })
  })
  await Promise.all(venuePromises)

If we remove this section:

        imageUrls: {
          set: ['https://assets.imgix.net/unsplash/citystreet.jpg']
        },

it works fine.

[mavilein]

@Siyfion : Thanks for the details! So your problems were scalar list values as well. 🙏
@Siyfion @nickluger : We implemented a fix and just triggered a new release. In a few minutes 1.13.3 will be available.