Deadlock in SQLSyntaxSupport.columns when connection pool is rapidly exhausted

[pvgoran]

I'm facing a tricky issue when I try to run multiple parallel queries using ScalikeJDBC's Query DSL. In essence, the code in SQLSyntaxSupportFeature.columns deadlocks against my DB.autoCommit() calls, and everything hangs until the connection pool throws with the "Timeout waiting for idle object" error.

Postgres table (selection of DB engine probably doesn't matter):

create table timeRecords (time timestamp with time zone not null unique);

build.sbt:

ThisBuild / version := "0.1.0-SNAPSHOT"

ThisBuild / scalaVersion := "3.1.3"

lazy val root = (project in file("."))
  .settings(
    name := "ScalikeColumnsDeadlock"
  )

scalacOptions ++= Seq("-deprecation", "-unchecked", "-feature", "-explaintypes")

libraryDependencies ++= Seq(
  "com.typesafe.scala-logging" %% "scala-logging" % "3.9.4",
  "ch.qos.logback" % "logback-classic" % "1.2.10",

  "org.scalikejdbc" %% "scalikejdbc" % "4.0.+",
  "org.postgresql" % "postgresql" % "42.3.+",
)

main.scala:

import java.time.{Duration, Instant}
import java.io.{InputStream, InputStreamReader, StringReader}
import java.net.InetSocketAddress
import java.sql.{Connection, SQLException}
import java.util.concurrent.{ConcurrentHashMap, Executor, Executors}

import scala.concurrent.{blocking, Await, Future}

import scala.collection.mutable
import scala.util.{Random, Success, Try}
import scala.jdk.CollectionConverters.*

import scalikejdbc.{ConnectionPool, ConnectionPoolSettings, ConnectionPoolFactory, DB, DBSession, IsolationLevel}
import scalikejdbc.interpolation.Implicits.*
import scalikejdbc.{applyUpdate, applyUpdateAndReturnGeneratedKey, insert, select, update, withSQL, AutoSession, Binders, DB, DBSession, ParameterBinderFactory, ResultName, SQLBuilder, SQLSyntaxSupport, TypeBinder, UpdateOperation, WrappedResultSet}

@main
def main(): Unit =
{
  println("Hello cruel world!")

  initScalike()

  val startTime = Instant.parse("2023-01-11T05:00:00Z")

  implicit val ec: scala.concurrent.ExecutionContext = scala.concurrent.ExecutionContext.fromExecutorService(
    Executors.newWorkStealingPool(10)
  )

  val combinedFuture = Future.traverse(1 to 10) { index =>
    Future { blocking {
      try {
        val thisTime = startTime.plusSeconds(index)
        createTimeRecord(thisTime)
      } catch { ex =>
        println(s"Thread ${threadId()} exception: $ex")
      }
    } }
  }

  Await.result(combinedFuture, concurrent.duration.Duration.Inf)

  println("Done.")
}

def initScalike() : Unit =
{
  Class.forName("org.postgresql.Driver")

  val poolSettings = ConnectionPoolSettings(
    // connectionTimeoutMillis = 5 * 60 * 1000,
  )
  ConnectionPool.singleton("jdbc:postgresql://localhost/test", "test", "test", poolSettings)
}

def threadId() : String =
  Thread.currentThread().getId.toString

def createTimeRecord(time : Instant) : Unit =
{
  DB.autoCommit { implicit session =>
    println(s"Thread ${threadId()}: start")
    TimeRecordDAO.createTimeRecord(time)
    println(s"Thread ${threadId()}: end")
  }
}

case class TimeRecord(
  time : Instant,
)

object TimeRecordDAO
{
  private val tr = S_TimeRecord.syntax("tr")
  private val _c_ = S_TimeRecord.column

  def createTimeRecord(time : Instant)
    (implicit s : DBSession) : Unit =
  {
    applyUpdate {
      insert
        .into(S_TimeRecord)
        .namedValues(
          _c_.time -> time,
        )
    }
  }

  object S_TimeRecord extends SQLSyntaxSupport[TimeRecord]
  {
    override val tableName = "timeRecords"
    override val useSnakeCaseColumnName = false

    def apply(imv : ResultName[TimeRecord])(rs : WrappedResultSet) : TimeRecord = TimeRecord(
      rs.zonedDateTime(imv.time).toInstant,
    )
  }
}

Output:

Hello cruel world!
14:34:52.923 [main] DEBUG scalikejdbc.ConnectionPool$ - Registered connection pool : ConnectionPool(url:jdbc:postgresql://localhost/test, user:test) using factory : <default>
14:34:52.925 [main] DEBUG scalikejdbc.ConnectionPool$ - Registered singleton connection pool : ConnectionPool(url:jdbc:postgresql://localhost/test, user:test)
Thread 15: start
Thread 19: start
Thread 17: start
Thread 22: start
Thread 18: start
Thread 23: start
Thread 14: start
Thread 16: start
Thread 21 exception: java.sql.SQLException: Cannot get a connection, pool error Timeout waiting for idle object
Thread 20 exception: java.sql.SQLException: Cannot get a connection, pool error Timeout waiting for idle object
Thread 23 exception: java.sql.SQLException: Cannot get a connection, pool error Timeout waiting for idle object
14:34:58.402 [ForkJoinPool-1-worker-4] DEBUG scalikejdbc.StatementExecutor$$anon$1 - SQL execution completed

  [SQL Execution]
   insert into timeRecords (time) values (2023-01-11T05:00:04Z); (1 ms)

  [Stack Trace]
    ...
    TimeRecordDAO$.createTimeRecord(main.scala:86)
    main$package$.$anonfun$2(main.scala:63)
    scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
    scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
    scalikejdbc.DBConnection.autoCommit(DBConnection.scala:264)
    scalikejdbc.DBConnection.autoCommit$(DBConnection.scala:15)
    scalikejdbc.DB.autoCommit(DB.scala:60)
    scalikejdbc.DB$.autoCommit$$anonfun$1(DB.scala:244)
    scalikejdbc.LoanPattern.using(LoanPattern.scala:23)
    scalikejdbc.LoanPattern.using$(LoanPattern.scala:14)
    scalikejdbc.DB$.using(DB.scala:140)
    scalikejdbc.DB$.autoCommit(DB.scala:244)
    main$package$.createTimeRecord(main.scala:61)
    main$package$.$anonfun$1$$anonfun$1$$anonfun$1(main.scala:34)
    main$package$.$anonfun$1$$anonfun$1$$anonfun$adapted$1(main.scala:38)
    ...

14:34:58.402 [ForkJoinPool-1-worker-2] DEBUG scalikejdbc.StatementExecutor$$anon$1 - SQL execution completed

  [SQL Execution]
   insert into timeRecords (time) values (2023-01-11T05:00:02Z); (1 ms)

  [Stack Trace]
    ...
    TimeRecordDAO$.createTimeRecord(main.scala:86)
    main$package$.$anonfun$2(main.scala:63)
    scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
    scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
    scalikejdbc.DBConnection.autoCommit(DBConnection.scala:264)
    scalikejdbc.DBConnection.autoCommit$(DBConnection.scala:15)
    scalikejdbc.DB.autoCommit(DB.scala:60)
    scalikejdbc.DB$.autoCommit$$anonfun$1(DB.scala:244)
    scalikejdbc.LoanPattern.using(LoanPattern.scala:23)
    scalikejdbc.LoanPattern.using$(LoanPattern.scala:14)
    scalikejdbc.DB$.using(DB.scala:140)
    scalikejdbc.DB$.autoCommit(DB.scala:244)
    main$package$.createTimeRecord(main.scala:61)
    main$package$.$anonfun$1$$anonfun$1$$anonfun$1(main.scala:34)
    main$package$.$anonfun$1$$anonfun$1$$anonfun$adapted$1(main.scala:38)
    ...

14:34:58.402 [ForkJoinPool-1-worker-9] DEBUG scalikejdbc.StatementExecutor$$anon$1 - SQL execution completed

  [SQL Execution]
   insert into timeRecords (time) values (2023-01-11T05:00:01Z); (1 ms)

  [Stack Trace]
    ...
    TimeRecordDAO$.createTimeRecord(main.scala:86)
    main$package$.$anonfun$2(main.scala:63)
    scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
    scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
    scalikejdbc.DBConnection.autoCommit(DBConnection.scala:264)
    scalikejdbc.DBConnection.autoCommit$(DBConnection.scala:15)
    scalikejdbc.DB.autoCommit(DB.scala:60)
    scalikejdbc.DB$.autoCommit$$anonfun$1(DB.scala:244)
    scalikejdbc.LoanPattern.using(LoanPattern.scala:23)
    scalikejdbc.LoanPattern.using$(LoanPattern.scala:14)
    scalikejdbc.DB$.using(DB.scala:140)
    scalikejdbc.DB$.autoCommit(DB.scala:244)
    main$package$.createTimeRecord(main.scala:61)
    main$package$.$anonfun$1$$anonfun$1$$anonfun$1(main.scala:34)
    main$package$.$anonfun$1$$anonfun$1$$anonfun$adapted$1(main.scala:38)
    ...

14:34:58.402 [ForkJoinPool-1-worker-6] DEBUG scalikejdbc.StatementExecutor$$anon$1 - SQL execution completed

  [SQL Execution]
   insert into timeRecords (time) values (2023-01-11T05:00:07Z); (1 ms)

  [Stack Trace]
    ...
    TimeRecordDAO$.createTimeRecord(main.scala:86)
    main$package$.$anonfun$2(main.scala:63)
    scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
    scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
    scalikejdbc.DBConnection.autoCommit(DBConnection.scala:264)
    scalikejdbc.DBConnection.autoCommit$(DBConnection.scala:15)
    scalikejdbc.DB.autoCommit(DB.scala:60)
    scalikejdbc.DB$.autoCommit$$anonfun$1(DB.scala:244)
    scalikejdbc.LoanPattern.using(LoanPattern.scala:23)
    scalikejdbc.LoanPattern.using$(LoanPattern.scala:14)
    scalikejdbc.DB$.using(DB.scala:140)
    scalikejdbc.DB$.autoCommit(DB.scala:244)
    main$package$.createTimeRecord(main.scala:61)
    main$package$.$anonfun$1$$anonfun$1$$anonfun$1(main.scala:34)
    main$package$.$anonfun$1$$anonfun$1$$anonfun$adapted$1(main.scala:38)
    ...

14:34:58.402 [ForkJoinPool-1-worker-13] DEBUG scalikejdbc.StatementExecutor$$anon$1 - SQL execution completed

  [SQL Execution]
   insert into timeRecords (time) values (2023-01-11T05:00:05Z); (1 ms)

  [Stack Trace]
    ...
    TimeRecordDAO$.createTimeRecord(main.scala:86)
    main$package$.$anonfun$2(main.scala:63)
    scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
    scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
    scalikejdbc.DBConnection.autoCommit(DBConnection.scala:264)
    scalikejdbc.DBConnection.autoCommit$(DBConnection.scala:15)
    scalikejdbc.DB.autoCommit(DB.scala:60)
    scalikejdbc.DB$.autoCommit$$anonfun$1(DB.scala:244)
    scalikejdbc.LoanPattern.using(LoanPattern.scala:23)
    scalikejdbc.LoanPattern.using$(LoanPattern.scala:14)
    scalikejdbc.DB$.using(DB.scala:140)
    scalikejdbc.DB$.autoCommit(DB.scala:244)
    main$package$.createTimeRecord(main.scala:61)
    main$package$.$anonfun$1$$anonfun$1$$anonfun$1(main.scala:34)
    main$package$.$anonfun$1$$anonfun$1$$anonfun$adapted$1(main.scala:38)
    ...

14:34:58.402 [ForkJoinPool-1-worker-1] DEBUG scalikejdbc.StatementExecutor$$anon$1 - SQL execution completed

  [SQL Execution]
   insert into timeRecords (time) values (2023-01-11T05:00:09Z); (1 ms)

  [Stack Trace]
    ...
    TimeRecordDAO$.createTimeRecord(main.scala:86)
    main$package$.$anonfun$2(main.scala:63)
    scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
    scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
    scalikejdbc.DBConnection.autoCommit(DBConnection.scala:264)
    scalikejdbc.DBConnection.autoCommit$(DBConnection.scala:15)
    scalikejdbc.DB.autoCommit(DB.scala:60)
    scalikejdbc.DB$.autoCommit$$anonfun$1(DB.scala:244)
    scalikejdbc.LoanPattern.using(LoanPattern.scala:23)
    scalikejdbc.LoanPattern.using$(LoanPattern.scala:14)
    scalikejdbc.DB$.using(DB.scala:140)
    scalikejdbc.DB$.autoCommit(DB.scala:244)
    main$package$.createTimeRecord(main.scala:61)
    main$package$.$anonfun$1$$anonfun$1$$anonfun$1(main.scala:34)
    main$package$.$anonfun$1$$anonfun$1$$anonfun$adapted$1(main.scala:38)
    ...

14:34:58.402 [ForkJoinPool-1-worker-11] DEBUG scalikejdbc.StatementExecutor$$anon$1 - SQL execution completed

  [SQL Execution]
   insert into timeRecords (time) values (2023-01-11T05:00:03Z); (1 ms)

  [Stack Trace]
    ...
    TimeRecordDAO$.createTimeRecord(main.scala:86)
    main$package$.$anonfun$2(main.scala:63)
    scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
    scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
    scalikejdbc.DBConnection.autoCommit(DBConnection.scala:264)
    scalikejdbc.DBConnection.autoCommit$(DBConnection.scala:15)
    scalikejdbc.DB.autoCommit(DB.scala:60)
    scalikejdbc.DB$.autoCommit$$anonfun$1(DB.scala:244)
    scalikejdbc.LoanPattern.using(LoanPattern.scala:23)
    scalikejdbc.LoanPattern.using$(LoanPattern.scala:14)
    scalikejdbc.DB$.using(DB.scala:140)
    scalikejdbc.DB$.autoCommit(DB.scala:244)
    main$package$.createTimeRecord(main.scala:61)
    main$package$.$anonfun$1$$anonfun$1$$anonfun$1(main.scala:34)
    main$package$.$anonfun$1$$anonfun$1$$anonfun$adapted$1(main.scala:38)
    ...

Thread 22: end
Thread 16: end
Thread 14: end
Thread 17: end
Thread 15: end
Thread 18: end
Thread 19: end
Done.

Here, we are trying to run 10 queries in parallel. The Commons2 connection pool uses 8 connections by default. As far as I understand, the code successfully obtains all 8 connections in parallel DB.autoCommit() calls (the other 2 DB.autoCommit() calls start waiting for a free connection). Then, the code in TimeRecordDAO.createTimeRecord() references _c_.time, which (as far as I understand) translates to a call to SQLSyntaxSupportFeature.field(), which ultimately references the lazy variable ColumnSQLSyntaxProvider.columns, whose initialization code, in turn, calls SQLSyntaxSupport.columns. And this property, finally, tries to borrow another database connection to load the list of table's columns. Since there are no available connections in the pool, this code blocks. All other threads that already acquired their connections in DB.autoCommit() also wait for the initialization code of ColumnSQLSyntaxProvider.columns to complete. This way, each of these 10 threads is stuck, either waiting for a connection in DB.autoCommit(), or waiting for a connection in SQLSyntaxSupport.columns, or waiting for completion of initialization code of ColumnSQLSyntaxProvider.columns.

When the pool declares timeout, 7 of 8 calls that acquired connections in DB.autoCommit() successfully complete their queries, and one of them fails for some reason. The other 2 DB.autoCommit() calls predictably fail.

Also, if I query 100 tasks instead of 10 tasks (within the same 10-thread ExecutionContext), most of them fail to insert a new record, not sure why.

The root problem here is that SQLSyntaxSupportFeature/ColumnSQLSyntaxProvider/SQLSyntaxSupport rely on the possibility to acquire a new connection from a pool by themselves, at an arbitrary moment of time. This issue would not occur if these classes used a session/connection obtained from the caller instead.

[pvgoran]

Looks like #1366 is caused by the same problem.

[seratch]

Hi @pvgoran, thanks for sharing this with details. Your analysis looks valid to me, too.

However, due to the current library design, passing the already acquired connection for column name loading may not be quickly feasible. I can't afford the time to make code changes because of my life priorities. If anyone is interested in improving this without breaking changes, I am happy to be a reviewer, though.

A workaround for this use case now would be explicitly listing the column names (meaning overriding columns) in the class instead of relying on the default auto-loading feature.

[pvgoran]

However, due to the current library design, passing the already acquired connection for column name loading may not be quickly feasible.

Yes, that's what I thought. It probably requires breaking changes (or at least introducing alternatives for multiple methods/properties).

A workaround for this use case now would be explicitly listing the column names (meaning overriding columns) in the class instead of relying on the default auto-loading feature.

Another work-around would be to manually reference SQLSyntaxSupport.columns in all objects/instances after configuring the pool (before doing any real database access). (I didn't actually try this, so maybe it won't work.)

@seratch Are there any (other) active ScalikeJDBC developers?

[seratch]

I am the sole maintainer who makes code changes these days. I am still committed to working on urgent issues such as critical security bugs. However, I don't see such severity on this possible problem mentioned here because production-grade apps tend to have a large enough connection pool size, so with that, the problem rarely occurs.

I do understand this issue can be a major one for you. However, for the above reasons, I won't work on improvements in the short term. If this potential issue is critical for you, plus you don't have time to contribute to this library, please consider switching to a different Scala library.

Again, I appreciate your time here to report this issue with great insights.