Slick 3.0 transactionally deadlocks

[poroszd]

Hi,
When I try to execute multiple transactions in separate threads, it happens to cause deadlock.

val tasks: IndexedSeq[Future[Int]] = 1 to 20 map { i =>
  val action = { table += i }.map { identity }
  database.run(action.transactionally)
}

Await.result(Future.sequence(tasks), 10.seconds)

This sample app always timeouts, without inserting any row in the test table.

However, it seems that the deadlock happens only in this constellation, as

• it works when transactionally is not used:

val tasks: IndexedSeq[Future[Int]] = 1 to 20 map { i =>
  val action = { table += i }.map { identity }
  database.run(action)
}

• it works without the mapping on DBIOAction:

val tasks: IndexedSeq[Future[Int]] = 1 to 20 map { i =>
  val action = { table += i }
  database.run(action.transactionally)
}

• it works with fewer threads:

val tasks: IndexedSeq[Future[Int]] = 1 to 10 map { i =>
  val action = { table += i }.map { identity }
  database.run(action.transactionally)
}

Could someone explain me what's happening, is this behavior intended, or am I missing something about transactions?
Also, I think it worths mentioning that I'm using Hikari connection pool, maybe it's related to that?

[kwark]

We are also suffering from this issue.

I took the time to make a quick project which demonstrates the issue: https://github.com/kwark/slick-deadlock

The issue not only occurs when using transactionally but also when using withPinnedSession
This is in combination with hikariCP connectionPool.

The numThreads configured for 2 slick threads, which results in a Hikari connectionPool of 10 connections.

However when the number of simultaneous task is high enough (in this case 20), it looks like the two slick threads are hanging and waiting for a connection from the pool.

"h2mem1-2" #17 daemon prio=5 os_prio=31 tid=0x00007f834d3d0800 nid=0x6303 waiting on condition [0x0000700001c69000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000076eb02c00> (a com.zaxxer.hikari.util.Java6ConcurrentBag$Synchronizer)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.locks.AbstractQueuedLongSynchronizer.doAcquireSharedNanos(AbstractQueuedLongSynchronizer.java:815)
at java.util.concurrent.locks.AbstractQueuedLongSynchronizer.tryAcquireSharedNanos(AbstractQueuedLongSynchronizer.java:1106)
at com.zaxxer.hikari.util.ConcurrentBag.borrow(ConcurrentBag.java:134)
at com.zaxxer.hikari.pool.BaseHikariPool.getConnection(BaseHikariPool.java:201)
at com.zaxxer.hikari.pool.BaseHikariPool.getConnection(BaseHikariPool.java:182)
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:93)
at slick.jdbc.hikaricp.HikariCPJdbcDataSource.createConnection(HikariCPJdbcDataSource.scala:12)
at slick.jdbc.JdbcBackend$BaseSession.conn$lzycompute(JdbcBackend.scala:415)
- locked <0x000000076b869f78> (a slick.jdbc.JdbcBackend$BaseSession)
at slick.jdbc.JdbcBackend$BaseSession.conn(JdbcBackend.scala:414)
at slick.jdbc.JdbcBackend$SessionDef$class.prepareStatement(JdbcBackend.scala:297)
at slick.jdbc.JdbcBackend$BaseSession.prepareStatement(JdbcBackend.scala:407)
at slick.jdbc.JdbcBackend$SessionDef$class.withPreparedStatement(JdbcBackend.scala:346)
at slick.jdbc.JdbcBackend$BaseSession.withPreparedStatement(JdbcBackend.scala:407)
at slick.driver.JdbcActionComponent$InsertActionComposerImpl.preparedInsert(JdbcActionComponent.scala:498)
at slick.driver.JdbcActionComponent$InsertActionComposerImpl$SingleInsertAction.run(JdbcActionComponent.scala:504)
at slick.driver.JdbcActionComponent$SimpleJdbcDriverAction.run(JdbcActionComponent.scala:32)
at slick.driver.JdbcActionComponent$SimpleJdbcDriverAction.run(JdbcActionComponent.scala:29)
at slick.backend.DatabaseComponent$DatabaseDef$$anon$2.liftedTree1$1(DatabaseComponent.scala:237)
at slick.backend.DatabaseComponent$DatabaseDef$$anon$2.run(DatabaseComponent.scala:237)
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)

"h2mem1-1" #16 daemon prio=5 os_prio=31 tid=0x00007f834e2ec800 nid=0x6103 waiting on condition [0x0000700001b66000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000076eb02c00> (a com.zaxxer.hikari.util.Java6ConcurrentBag$Synchronizer)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.locks.AbstractQueuedLongSynchronizer.doAcquireSharedNanos(AbstractQueuedLongSynchronizer.java:815)
at java.util.concurrent.locks.AbstractQueuedLongSynchronizer.tryAcquireSharedNanos(AbstractQueuedLongSynchronizer.java:1106)
at com.zaxxer.hikari.util.ConcurrentBag.borrow(ConcurrentBag.java:134)
at com.zaxxer.hikari.pool.BaseHikariPool.getConnection(BaseHikariPool.java:201)
at com.zaxxer.hikari.pool.BaseHikariPool.getConnection(BaseHikariPool.java:182)
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:93)
at slick.jdbc.hikaricp.HikariCPJdbcDataSource.createConnection(HikariCPJdbcDataSource.scala:12)
at slick.jdbc.JdbcBackend$BaseSession.conn$lzycompute(JdbcBackend.scala:415)
- locked <0x000000076b86a118> (a slick.jdbc.JdbcBackend$BaseSession)
at slick.jdbc.JdbcBackend$BaseSession.conn(JdbcBackend.scala:414)
at slick.jdbc.JdbcBackend$SessionDef$class.prepareStatement(JdbcBackend.scala:297)
at slick.jdbc.JdbcBackend$BaseSession.prepareStatement(JdbcBackend.scala:407)
at slick.jdbc.JdbcBackend$SessionDef$class.withPreparedStatement(JdbcBackend.scala:346)
at slick.jdbc.JdbcBackend$BaseSession.withPreparedStatement(JdbcBackend.scala:407)
at slick.driver.JdbcActionComponent$InsertActionComposerImpl.preparedInsert(JdbcActionComponent.scala:498)
at slick.driver.JdbcActionComponent$InsertActionComposerImpl$SingleInsertAction.run(JdbcActionComponent.scala:504)
at slick.driver.JdbcActionComponent$SimpleJdbcDriverAction.run(JdbcActionComponent.scala:32)
at slick.driver.JdbcActionComponent$SimpleJdbcDriverAction.run(JdbcActionComponent.scala:29)
at slick.backend.DatabaseComponent$DatabaseDef$$anon$2.liftedTree1$1(DatabaseComponent.scala:237)
at slick.backend.DatabaseComponent$DatabaseDef$$anon$2.run(DatabaseComponent.scala:237)
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)

But there are no free connections anymore according to the HikariCP logging:

[HikariCP connection filler (pool h2mem1)] DEBUG com.zaxxer.hikari.pool.HikariPool - After fill pool stats h2mem1 (total=10, inUse=10, avail=0, waiting=2)

[szeiger]

Related discussion: https://groups.google.com/d/msgid/scalaquery/b8e807e0-439d-439a-a025-d6ccde12c74f%40googlegroups.com?utm_medium=email&utm_source=footer

[jilen]

Is there any workaround? I think this is a big problem for a production enviornment. I have suffered from it many times and had to restart the whole application.

[francescopellegrini]

We are also suffering from this issue.
We are reducing thread amount and using a synchronous thread pool to prevent this issue from happening.

[jilen]

@MrPelle How to use an synchronous thread pool

[jilen]

@szeiger I think there is something wrong with slick exection model. You may look at the simple benchmark (Source Code) I've made for testing very simple (non-)transaction operations.

Execution time grow rapdily as concurrency level increase.

  def trans(userId: Long, order: Order) = DB.run {
    val mutateIO = sqlu"update user set remain = remain - ${order.totalFee} where id = ${userId}"
    val insertIO = Orders += order
    insertIO >> mutateIO
  }

[edrevo]

+1. It would also be nice to know when this bug was introduced, so an earlier version could be used as a workaround.

[edrevo]

Slick 2.x doesn't seem to be affected, but the whole Slick 3.x branch is.

[szeiger]

Workaround until we fix this properly (as explained in the mailing list thread): Set the maximum number of connections larger than thread pool size + queue size.

[JakubKahovec]

Is there a roadmap when this fix is going to be part of official Slick ?

[utaladriz]

I experimenting the same problem during a massive insert.
I don't get it how you can set the maximum number of connections when this is setted by slick based in thread pool size

This is my actor code.

 for (file <- files.get) {
                  val f = file.copy(taskId = t.id, date = Some(new Timestamp(new Date().getTime)))
                  bd.run(insert(f)).onComplete({
                    case Success(af) =>
                      val dir = new File(taskDir, af.id.get.toString)
                      dir.mkdir()
                      self ! EndJob(Work("start", t, af, dir, t.accion.get, 0))
                    case Failure(e) =>
                      log.error(e.getMessage, e)
                  }
                  )
                }

[utaladriz]

Right now i'm trying with this configuration:

numThreads = 60 queueSize=200

[szeiger]

@utaladriz You can set maxConnections (for HikariCP):

      *   <li>`maxConnections` (Int, optional, default: `numThreads` * 5): The maximum number of
      *     connections in the pool.</li>

Since the detault is numThreads * 5 = 300, which is greater than numThreads + queueSize, there should not be any need to change it.

[kwark]

I backported my slick deadlock fix (#1461) to 3.1.1 and published it to a bintray repo as version 3.1.1.1

If you are suffering from deadlocks you might want to try out that version.
Instructions can be found here: https://github.com/kwark/slick/blob/3.1-deadlock/README.md

[szeiger]

Fixed in #1461