Slick 5ms overhead when querying "SELECT 1" from MySQL

Akka
1

Trying to understand if I’m doing something wrong here, but I’m getting 5ms of overhead for each slick stream I’m creating. The query itself takes 1ms to run SELECT 1 which does nothing server side, the connection is to local host, and the configuration uses a connection pool.

Here is the full example:

import akka.actor.ActorSystem
import akka.stream.alpakka.slick.scaladsl.{Slick, SlickSession}
import akka.stream.scaladsl.Sink
import com.typesafe.config.ConfigFactory
import org.scalatest.funsuite.AnyFunSuite
import slick.jdbc.MySQLProfile.api._
import slick.jdbc.{MySQLProfile, SQLActionBuilder, SetParameter}

import scala.concurrent.Await
import scala.concurrent.duration.DurationInt
import scala.jdk.CollectionConverters._

class SlickTest extends AnyFunSuite
{
    implicit lazy val system: ActorSystem = ActorSystem()

    test("Doing nothing for 5ms")
    {
        implicit lazy val session: SlickSession = {
            val settings = Map(
                "slick.connectionPool" -> "HikariCP",
                "slick.driver" -> "com.mysql.cj.jdbc.Driver",
                "slick.url" -> *,
                "slick.user" -> *,
                "slick.password" -> *,
                "slick.numThreads" -> 10
            )
            val config = ConfigFactory.parseMap(settings.asJava)
            val db = Database.forConfig("slick", config)
            val session: SlickSession = SlickSession.forDbAndProfile(db, MySQLProfile)
            system.registerOnTermination(() => session.close())
            session
        }

        (0 to 30).foreach { _ =>
            System.out.println(s"BEGIN: " + System.currentTimeMillis())
            val sql = SQLActionBuilder("SELECT 1", SetParameter.SetUnit)
            val superExpensiveQuery = Slick.source(sql.as[Int])
            Await.result(superExpensiveQuery.runWith(Sink.ignore), 10.seconds)
            System.out.println(s"END: " + System.currentTimeMillis())
        }
    }
}

From the tail end of that test here is what is logged:

BEGIN: 1666075622643
[18/10/2022 06:47:02.644] [DEBUG] [slick.basic.BasicBackend.stream] Signaling onSubscribe(slick.jdbc.JdbcBackend$JdbcStreamingActionContext@603305da)
[18/10/2022 06:47:02.644] [DEBUG] [slick.basic.BasicBackend.action] #1: StreamingResultAction [SELECT 1]
[18/10/2022 06:47:02.644] [DEBUG] [slick.basic.BasicBackend.stream] Starting initial streaming action, realDemand = 16
[18/10/2022 06:47:02.644] [DEBUG] [slick.jdbc.JdbcBackend.statement] Preparing statement: SELECT 1
[18/10/2022 06:47:02.645] [DEBUG] [slick.jdbc.JdbcBackend.statement] Executing prepared statement: HikariProxyPreparedStatement@1983378226 wrapping com.mysql.cj.jdbc.ClientPreparedStatement: SELECT 1
[18/10/2022 06:47:02.645] [DEBUG] [s.j.J.statementAndParameter] Executing prepared statement: HikariProxyPreparedStatement@1983378226 wrapping com.mysql.cj.jdbc.ClientPreparedStatement: SELECT 1
[18/10/2022 06:47:02.647] [DEBUG] [slick.jdbc.JdbcBackend.benchmark] Execution of prepared statement took 2ms
[18/10/2022 06:47:02.648] [DEBUG] [slick.jdbc.StatementInvoker.result] /---\
[18/10/2022 06:47:02.648] [DEBUG] [slick.jdbc.StatementInvoker.result] | 1 |
[18/10/2022 06:47:02.648] [DEBUG] [slick.jdbc.StatementInvoker.result] | 1 |
[18/10/2022 06:47:02.648] [DEBUG] [slick.jdbc.StatementInvoker.result] |---|
[18/10/2022 06:47:02.648] [DEBUG] [slick.jdbc.StatementInvoker.result] | 1 |
[18/10/2022 06:47:02.648] [DEBUG] [slick.jdbc.StatementInvoker.result] \---/
[18/10/2022 06:47:02.648] [DEBUG] [slick.basic.BasicBackend.stream] Signaling onComplete()
[18/10/2022 06:47:02.648] [DEBUG] [slick.basic.BasicBackend.stream] Sent up to 16 elements - Stream completely delivered
[18/10/2022 06:47:02.648] [DEBUG] [slick.basic.BasicBackend.stream] Finished streaming action
END: 1666075622648
BEGIN: 1666075622648
[18/10/2022 06:47:02.649] [DEBUG] [slick.basic.BasicBackend.stream] Signaling onSubscribe(slick.jdbc.JdbcBackend$JdbcStreamingActionContext@3163f88a)
[18/10/2022 06:47:02.650] [DEBUG] [slick.basic.BasicBackend.action] #1: StreamingResultAction [SELECT 1]
[18/10/2022 06:47:02.650] [DEBUG] [slick.basic.BasicBackend.stream] Starting initial streaming action, realDemand = 16
[18/10/2022 06:47:02.650] [DEBUG] [slick.jdbc.JdbcBackend.statement] Preparing statement: SELECT 1
[18/10/2022 06:47:02.651] [DEBUG] [slick.jdbc.JdbcBackend.statement] Executing prepared statement: HikariProxyPreparedStatement@905949325 wrapping com.mysql.cj.jdbc.ClientPreparedStatement: SELECT 1
[18/10/2022 06:47:02.651] [DEBUG] [s.j.J.statementAndParameter] Executing prepared statement: HikariProxyPreparedStatement@905949325 wrapping com.mysql.cj.jdbc.ClientPreparedStatement: SELECT 1
[18/10/2022 06:47:02.653] [DEBUG] [slick.jdbc.JdbcBackend.benchmark] Execution of prepared statement took 1ms
[18/10/2022 06:47:02.654] [DEBUG] [slick.jdbc.StatementInvoker.result] /---\
[18/10/2022 06:47:02.654] [DEBUG] [slick.jdbc.StatementInvoker.result] | 1 |
[18/10/2022 06:47:02.654] [DEBUG] [slick.jdbc.StatementInvoker.result] | 1 |
[18/10/2022 06:47:02.654] [DEBUG] [slick.jdbc.StatementInvoker.result] |---|
[18/10/2022 06:47:02.654] [DEBUG] [slick.jdbc.StatementInvoker.result] | 1 |
[18/10/2022 06:47:02.654] [DEBUG] [slick.jdbc.StatementInvoker.result] \---/
[18/10/2022 06:47:02.654] [DEBUG] [slick.basic.BasicBackend.stream] Signaling onComplete()
[18/10/2022 06:47:02.654] [DEBUG] [slick.basic.BasicBackend.stream] Sent up to 16 elements - Stream completely delivered
[18/10/2022 06:47:02.654] [DEBUG] [slick.basic.BasicBackend.stream] Finished streaming action
END: 1666075622654

I’ve got PHP drivers that run that in well under 1ms. Any thoughts?

Thanks,
Terence

1 Like