Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add slow query logger based on Doobie #4993

Merged
merged 5 commits into from
May 22, 2024
Merged
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 0 additions & 1 deletion build.sbt
Original file line number Diff line number Diff line change
@@ -912,7 +912,6 @@ lazy val kamonSettings = Seq(
"io.kamon" %% "kamon-core" % kamonVersion,
"io.kamon" %% "kamon-executors" % kamonVersion,
"io.kamon" %% "kamon-jaeger" % kamonVersion,
"io.kamon" %% "kamon-jdbc" % kamonVersion,
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Slow query logging was the only feature we used from it so we can just get rid of it now

"io.kamon" %% "kamon-logback" % kamonVersion,
"io.kamon" %% "kamon-prometheus" % kamonVersion,
"io.kamon" %% "kamon-scala-future" % kamonVersion,
3 changes: 3 additions & 0 deletions delta/app/src/main/resources/app.conf
Original file line number Diff line number Diff line change
@@ -41,6 +41,9 @@ app {
# The duration after an entry in the cache expires
expire-after = 10 minutes
}

# Threshold from which a query is considered slow and will be logged
slow-query-threshold = 2 seconds
}

# Database export configuration
Original file line number Diff line number Diff line change
@@ -0,0 +1,69 @@
package ch.epfl.bluebrain.nexus.delta.sourcing

import cats.effect.IO
import ch.epfl.bluebrain.nexus.delta.kernel.Logger
import ch.epfl.bluebrain.nexus.delta.sourcing.event.Event
import ch.epfl.bluebrain.nexus.delta.sourcing.state.State
import doobie.util.log
import doobie.util.log.{LogEvent, LogHandler}
import io.circe.Json

import scala.concurrent.duration.FiniteDuration

object QueryLogHandler {

private val logger = Logger[QueryLogHandler.type]

def apply(poolName: String, slowQueryThreshold: FiniteDuration): LogHandler[IO] = new LogHandler[IO] {
override def run(logEvent: LogEvent): IO[Unit] = logEvent match {
case log.Success(sql, args, label, exec, processing) if exec > slowQueryThreshold =>
logger.warn(s"""[$poolName] Slow Statement Execution:
|
| ${formatQuery(sql)}
|
| arguments = ${formatArguments(args)}
| label = $label
| elapsed = ${exec.toMillis} ms exec + ${processing.toMillis} ms processing (${(exec + processing).toMillis} ms total)
""".stripMargin)
case log.Success(sql, args, label, exec, processing) =>
logger.debug(s"""[$poolName] Successful Statement Execution:
|
| ${formatQuery(sql)}
|
| arguments = ${formatArguments(args)}
| label = $label
| elapsed = ${exec.toMillis} ms exec + ${processing.toMillis} ms processing (${(exec + processing).toMillis} ms total)
""".stripMargin)
case log.ProcessingFailure(sql, args, label, exec, processing, failure) =>
logger.error(failure)(s"""[$poolName] Failed Resultset Processing:
|
| ${formatQuery(sql)}
|
| arguments = ${formatArguments(args)}
| label = $label
| elapsed = ${exec.toMillis} ms exec + ${processing.toMillis} ms processing (failed) (${(exec + processing).toMillis.toString} ms total)
""".stripMargin)
case log.ExecFailure(sql, args, label, exec, failure) =>
logger.error(failure)(s"""[$poolName] Failed Statement Execution:
|
| ${formatQuery(sql)}
|
| arguments = ${formatArguments(args)}
| label = $label
| elapsed = ${exec.toMillis} ms exec (failed)
""".stripMargin)
}

private def formatQuery(sql: String) = sql.linesIterator.dropWhile(_.trim.isEmpty).mkString("\n ")

private def formatArguments(args: List[Any]) = args
.map {
case _: Json => "{json blob}"
case e: Event => s"{event ${e.getClass.getSimpleName}}"
case s: State => s"{state ${s.getClass.getSimpleName}}"
case other => other.toString
}
.mkString("[", ", ", "]")
}

}
Original file line number Diff line number Diff line change
@@ -95,6 +95,7 @@ object Transactors {
username,
Secret(password),
tablesAutocreate = false,
5.seconds,
CacheConfig(500, 10.minutes)
)
init(databaseConfig)
@@ -103,6 +104,7 @@ object Transactors {
def init(
config: DatabaseConfig
): Resource[IO, Transactors] = {

def transactor(access: DatabaseAccess, readOnly: Boolean, poolName: String): Resource[IO, HikariTransactor[IO]] = {
for {
ec <- ExecutionContexts.fixedThreadPool[IO](access.poolSize)
@@ -118,7 +120,7 @@ object Transactors {
ds.setReadOnly(readOnly)
ds
})(ds => IO.delay(ds.close()))
} yield HikariTransactor[IO](dataSource, ec, None)
} yield HikariTransactor[IO](dataSource, ec, Some(QueryLogHandler(poolName, config.slowQueryThreshold)))
}

val transactors = for {
Original file line number Diff line number Diff line change
@@ -6,6 +6,8 @@ import ch.epfl.bluebrain.nexus.delta.sourcing.config.DatabaseConfig.DatabaseAcce
import pureconfig.ConfigReader
import pureconfig.generic.semiauto.deriveReader

import scala.concurrent.duration.FiniteDuration

/**
* Database configuration
* @param read
@@ -22,6 +24,8 @@ import pureconfig.generic.semiauto.deriveReader
* The database password
* @param tablesAutocreate
* When true it creates the tables on service boot
* @param slowQueryThreshold
* Threshold allowing to trigger a warning log when a query execution time reaches this limit
* @param cache
* The cache configuration for the partitions cache
*/
@@ -33,6 +37,7 @@ final case class DatabaseConfig(
username: String,
password: Secret[String],
tablesAutocreate: Boolean,
slowQueryThreshold: FiniteDuration,
cache: CacheConfig
)

3 changes: 3 additions & 0 deletions ship/src/main/resources/ship-default.conf
Original file line number Diff line number Diff line change
@@ -17,6 +17,9 @@ ship {
expire-after = 10 minutes
}

# Threshold from which a query is considered slow and will be logged
slow-query-threshold = 2 seconds

access {
# the database host
host = 127.0.0.1
Original file line number Diff line number Diff line change
@@ -1053,7 +1053,7 @@ class SearchConfigIndexingSpec extends BaseIntegrationSpec {
}
}

"have the correct configuration for a simulation campaign" in {
"have the correct configuration for a simulation campaign" in {
val query = queryField(emodelId, "objectOfStudy")
val expected =
json"""{