diff --git a/build.sbt b/build.sbt index 56a65b2df3..693a180251 100755 --- a/build.sbt +++ b/build.sbt @@ -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, "io.kamon" %% "kamon-logback" % kamonVersion, "io.kamon" %% "kamon-prometheus" % kamonVersion, "io.kamon" %% "kamon-scala-future" % kamonVersion, diff --git a/delta/app/src/main/resources/app.conf b/delta/app/src/main/resources/app.conf index eda9a41c45..fab990a813 100644 --- a/delta/app/src/main/resources/app.conf +++ b/delta/app/src/main/resources/app.conf @@ -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 diff --git a/delta/sourcing-psql/src/main/scala/ch/epfl/bluebrain/nexus/delta/sourcing/QueryLogHandler.scala b/delta/sourcing-psql/src/main/scala/ch/epfl/bluebrain/nexus/delta/sourcing/QueryLogHandler.scala new file mode 100644 index 0000000000..c56406d5ae --- /dev/null +++ b/delta/sourcing-psql/src/main/scala/ch/epfl/bluebrain/nexus/delta/sourcing/QueryLogHandler.scala @@ -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("[", ", ", "]") + } + +} diff --git a/delta/sourcing-psql/src/main/scala/ch/epfl/bluebrain/nexus/delta/sourcing/Transactors.scala b/delta/sourcing-psql/src/main/scala/ch/epfl/bluebrain/nexus/delta/sourcing/Transactors.scala index 90f6ed6c2c..fd8ce790be 100644 --- a/delta/sourcing-psql/src/main/scala/ch/epfl/bluebrain/nexus/delta/sourcing/Transactors.scala +++ b/delta/sourcing-psql/src/main/scala/ch/epfl/bluebrain/nexus/delta/sourcing/Transactors.scala @@ -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 { diff --git a/delta/sourcing-psql/src/main/scala/ch/epfl/bluebrain/nexus/delta/sourcing/config/DatabaseConfig.scala b/delta/sourcing-psql/src/main/scala/ch/epfl/bluebrain/nexus/delta/sourcing/config/DatabaseConfig.scala index e7dedfa3cc..96f9edf1c3 100644 --- a/delta/sourcing-psql/src/main/scala/ch/epfl/bluebrain/nexus/delta/sourcing/config/DatabaseConfig.scala +++ b/delta/sourcing-psql/src/main/scala/ch/epfl/bluebrain/nexus/delta/sourcing/config/DatabaseConfig.scala @@ -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 ) diff --git a/ship/src/main/resources/ship-default.conf b/ship/src/main/resources/ship-default.conf index 21ff0be44e..712d754454 100644 --- a/ship/src/main/resources/ship-default.conf +++ b/ship/src/main/resources/ship-default.conf @@ -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 diff --git a/tests/src/test/scala/ch/epfl/bluebrain/nexus/tests/kg/SearchConfigIndexingSpec.scala b/tests/src/test/scala/ch/epfl/bluebrain/nexus/tests/kg/SearchConfigIndexingSpec.scala index b055596464..929f04ee9b 100644 --- a/tests/src/test/scala/ch/epfl/bluebrain/nexus/tests/kg/SearchConfigIndexingSpec.scala +++ b/tests/src/test/scala/ch/epfl/bluebrain/nexus/tests/kg/SearchConfigIndexingSpec.scala @@ -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"""{