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.

Sign up for GitHub

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

Jump to bottom

fix: ExecutionTimeRecorder to work when no label for LabeledHistogram #1674

Merged
merged 4 commits into from
Aug 30, 2023
Merged

fix: ExecutionTimeRecorder to work when no label for LabeledHistogram #1674

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
bac1e3d
chore: removed grafana dashboards
jachro Aug 28, 2023
dcba635
fix: ExecutionTimeRecorder to work when no label for LabeledHistogram
jachro Aug 28, 2023
b855ba5
fix: compilation issue
jachro Aug 28, 2023
928184f
Merge branch 'development'
jachro Aug 30, 2023
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
46 changes: 23 additions & 23 deletions graph-commons/src/main/scala/io/renku/logging/ExecutionTimeRecorder.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,7 +18,7 @@

package io.renku.logging

import cats.effect.{Clock, Sync}
import cats.effect.{Clock, Resource, Sync}
import cats.syntax.all._
import cats.{Applicative, Monad}
import com.typesafe.config.{Config, ConfigFactory}
Expand Down Expand Up @@ -76,29 +76,29 @@ class ExecutionTimeRecorderImpl[F[_]: Sync: Clock: Logger](
override def measureExecutionTime[A](
block: F[A],
maybeHistogramLabel: Option[String Refined NonEmpty] = None
): F[(ElapsedTime, A)] = Clock[F]
.timed {
maybeHistogram match {
case None => block
case Some(histogram) =>
for {
maybeTimer <- maybeStartTimer(histogram, maybeHistogramLabel)
result <- block
_ <- maybeTimer.map(_.observeDuration.void).getOrElse(().pure[F])
} yield result
): F[(ElapsedTime, A)] =
Clock[F]
.timed {
maybeHistogram match {
case None => block
case Some(histogram) => timerResource(histogram, maybeHistogramLabel).surround(block)
}
}
}
.map { case (elapsedTime, result) => ElapsedTime(elapsedTime) -> result }

private def maybeStartTimer(histogram: Histogram[F], maybeHistogramLabel: Option[String Refined NonEmpty]) =
histogram -> maybeHistogramLabel match {
case (h: SingleValueHistogram[F], None) => h.startTimer().map(_.some)
case (h: LabeledHistogram[F], Some(label)) => h.startTimer(label.value).map(_.some)
case (h: SingleValueHistogram[F], Some(label)) =>
Logger[F].error(s"Label $label sent for a Single Value Histogram ${h.name}") >> None.pure[F]
case (h: LabeledHistogram[F], None) =>
Logger[F].error(s"No label sent for a Labeled Histogram ${h.name}") >> None.pure[F]
}
.map { case (elapsedTime, result) => ElapsedTime(elapsedTime) -> result }

private lazy val timerResource
: (Histogram[F], Option[String Refined NonEmpty]) => Resource[F, Option[Histogram.Timer[F]]] = {
case (h: SingleValueHistogram[F], None) =>
Resource.make(h.startTimer().map(_.some))(_.map(_.observeDuration.void).getOrElse(().pure[F]))
case (h: LabeledHistogram[F], Some(label)) =>
Resource.make(h.startTimer(label.value).map(_.some))(_.map(_.observeDuration.void).getOrElse(().pure[F]))
case (_: LabeledHistogram[F], None) =>
Resource.pure[F, Option[Histogram.Timer[F]]](Option.empty[Histogram.Timer[F]])
case (h: SingleValueHistogram[F], Some(label)) =>
Resource
.pure[F, Option[Histogram.Timer[F]]](Option.empty[Histogram.Timer[F]])
.evalTap(_ => Logger[F].error(s"Label $label sent for a Single Value Histogram ${h.name}"))
}
}

object ExecutionTimeRecorder {
Expand Down
4 changes: 3 additions & 1 deletion graph-commons/src/main/scala/io/renku/triplesstore/ProjectSparqlClient.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,9 +33,11 @@ import org.typelevel.log4cats.Logger
trait ProjectSparqlClient[F[_]] extends SparqlClient[F]

object ProjectSparqlClient {
def apply[F[_]: Monad: Logger: SparqlQueryTimeRecorder](c: SparqlClient[F]) =

def apply[F[_]: Monad: Logger: SparqlQueryTimeRecorder](c: SparqlClient[F]): ProjectSparqlClient[F] =
new ProjectSparqlClient[F] {
private[this] val rec = SparqlQueryTimeRecorder[F].instance

override def update(request: SparqlUpdate) = {
val label = histogramLabel(request)
val work = c.update(request)
Expand Down
150 changes: 74 additions & 76 deletions graph-commons/src/test/scala/io/renku/logging/ExecutionTimeRecorderSpec.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -28,59 +28,59 @@ import io.renku.generators.CommonGraphGenerators._
import io.renku.generators.Generators.Implicits._
import io.renku.generators.Generators._
import io.renku.interpreters.TestLogger
import io.renku.interpreters.TestLogger.Level.{Error, Warn}
import io.renku.interpreters.TestLogger.Level.Warn
import io.renku.logging.ExecutionTimeRecorder.ElapsedTime
import io.renku.metrics.{Histogram, LabeledHistogram, SingleValueHistogram}
import io.renku.testtools.IOSpec
import io.renku.testtools.CustomAsyncIOSpec
import org.scalacheck.Gen.finiteDuration
import org.scalamock.scalatest.MockFactory
import org.scalamock.scalatest.AsyncMockFactory
import org.scalatest.BeforeAndAfterEach
import org.scalatest.matchers.should
import org.scalatest.wordspec.AnyWordSpec
import org.scalatestplus.scalacheck.ScalaCheckPropertyChecks
import org.scalatest.wordspec.AsyncWordSpec

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

class ExecutionTimeRecorderSpec
extends AnyWordSpec
with IOSpec
with MockFactory
with ScalaCheckPropertyChecks
with should.Matchers {
extends AsyncWordSpec
with CustomAsyncIOSpec
with AsyncMockFactory
with should.Matchers
with BeforeAndAfterEach {

"measureExecutionTime" should {

"measure execution time of the given block and provide it to the output" in new TestCase {
"measure execution time of the given block and provide it to the output" in {

val elapsedTime = durations(min = 100 millis, max = 500 millis).map(ElapsedTime(_)).generateOne
val blockOut = nonEmptyStrings().generateOne
block.expects().returning(Temporal[IO].delayBy(blockOut.pure[IO], elapsedTime.value millis))

val actualElapsedTime -> actualOut = executionTimeRecorder.measureExecutionTime[String](block()).unsafeRunSync()

actualElapsedTime should be >= elapsedTime
actualOut shouldBe blockOut
executionTimeRecorder.measureExecutionTime[String](block()).asserting { case actualElapsedTime -> actualOut =>
actualElapsedTime should be >= elapsedTime
actualOut shouldBe blockOut
}
}

"let the block failure propagate" in new TestCase {
"let the block failure propagate" in {

val exception = exceptions.generateOne
block.expects().returning(exception.raiseError[IO, String])

intercept[Exception] {
executionTimeRecorder
.measureExecutionTime[String](block())
.unsafeRunSync()
} shouldBe exception
executionTimeRecorder
.measureExecutionTime[String](block())
.assertThrowsError[Exception](_ shouldBe exception)
.unsafeRunSync()
}

"made the given histogram to collect process' execution time - case without a label" in new TestCase {
"made the given histogram to collect process execution time - case without a label" in {

val histogram = mock[SingleValueHistogram[IO]]
val histogramTimer = mock[Histogram.Timer[IO]]
(histogram.startTimer _).expects().returning(histogramTimer.pure[IO])
(() => histogramTimer.observeDuration).expects().returning(nonNegativeDoubles().generateOne.value.pure[IO])

override val executionTimeRecorder = new ExecutionTimeRecorderImpl(loggingThreshold, Some(histogram))
val executionTimeRecorder = new ExecutionTimeRecorderImpl(loggingThreshold, Some(histogram))

val blockOut = nonEmptyStrings().generateOne
block.expects().returning(blockOut.pure[IO])
Expand All @@ -90,17 +90,18 @@ class ExecutionTimeRecorderSpec
.measureExecutionTime[String] {
Temporal[IO].delayBy(block(), blockExecutionTime millis)
}
.unsafeRunSync()
.assertNoException
}

"made the given histogram to collect process' execution time - case with a label" in new TestCase {
"made the given histogram to collect process execution time - case with a label" in {

val label: String Refined NonEmpty = "label"
val histogram = mock[LabeledHistogram[IO]]
val histogramTimer = mock[Histogram.Timer[IO]]
(histogram.startTimer _).expects(label.value).returning(histogramTimer.pure[IO])
(() => histogramTimer.observeDuration).expects().returning(nonNegativeDoubles().generateOne.value.pure[IO])

override val executionTimeRecorder = new ExecutionTimeRecorderImpl(loggingThreshold, Some(histogram))
val executionTimeRecorder = new ExecutionTimeRecorderImpl(loggingThreshold, Some(histogram))

val blockOut = nonEmptyStrings().generateOne
block.expects().returning(blockOut.pure[IO])
Expand All @@ -111,10 +112,12 @@ class ExecutionTimeRecorderSpec
Temporal[IO].delayBy(block(), blockExecutionTime millis),
Some(label)
)
.unsafeRunSync()
.assertNoException >>
IO(logger.expectNoLogs())
}

"log an error when collecting process' execution time fails due to histogram misconfiguration" in new TestCase {
"made the given labelled histogram not to collect the process execution time when no label given" in {

val histogram = new LabeledHistogram[IO] {
override val name = "metric"
override val help = "help"
Expand All @@ -125,7 +128,7 @@ class ExecutionTimeRecorderSpec
override def observe(labelValue: String, amt: Double): IO[Unit] = ???
}

override val executionTimeRecorder = new ExecutionTimeRecorderImpl(loggingThreshold, Some(histogram))
val executionTimeRecorder = new ExecutionTimeRecorderImpl(loggingThreshold, Some(histogram))

val blockOut = nonEmptyStrings().generateOne
block.expects().returning(blockOut.pure[IO])
Expand All @@ -135,16 +138,15 @@ class ExecutionTimeRecorderSpec
.measureExecutionTime[String] {
Temporal[IO].delayBy(block(), blockExecutionTime millis)
}
.unsafeRunSync()

logger.loggedOnly(Error(s"No label sent for a Labeled Histogram ${histogram.name}"))
.assertNoException >>
IO(logger.expectNoLogs())
}
}

"logExecutionTimeWhen" should {

"log warning with the phrase returned from the given partial function if it gets applied " +
"and the elapsed time is >= threshold" in new TestCase {
"and the elapsed time is >= threshold" in {
import executionTimeRecorder._

val elapsedTime = elapsedTimes.retryUntil(_.value >= loggingThreshold.value).generateOne
Expand All @@ -156,13 +158,12 @@ class ExecutionTimeRecorderSpec
.flatMap(logExecutionTimeWhen { case _ =>
blockExecutionMessage
})
.unsafeRunSync() shouldBe blockOut

logger.loggedOnly(Warn(s"$blockExecutionMessage in ${elapsedTime}ms"))
.asserting(_ shouldBe blockOut) >>
IO(logger.loggedOnly(Warn(s"$blockExecutionMessage in ${elapsedTime}ms")))
}

"not log a message if the given partial function does get applied " +
"but the elapsed time is < threshold" in new TestCase {
"but the elapsed time is < threshold" in {
import executionTimeRecorder._

val elapsedTime = ElapsedTime(loggingThreshold.value - 1)
Expand All @@ -174,12 +175,11 @@ class ExecutionTimeRecorderSpec
.flatMap(logExecutionTimeWhen { case _ =>
blockExecutionMessage
})
.unsafeRunSync() shouldBe blockOut

logger.expectNoLogs()
.asserting(_ shouldBe blockOut) >>
IO(logger.expectNoLogs())
}

"not log a message if the given partial function does not get applied" in new TestCase {
"not log a message if the given partial function does not get applied" in {
import executionTimeRecorder._

val elapsedTime = elapsedTimes.generateOne
Expand All @@ -191,15 +191,14 @@ class ExecutionTimeRecorderSpec
.flatMap(logExecutionTimeWhen { case "" =>
blockExecutionMessage
})
.unsafeRunSync() shouldBe blockOut

logger.expectNoLogs()
.asserting(_ shouldBe blockOut) >>
IO(logger.expectNoLogs())
}
}

"logExecutionTime" should {

"log warning with the given phrase when elapsed time is >= threshold" in new TestCase {
"log warning with the given phrase when elapsed time is >= threshold" in {
import executionTimeRecorder._

val elapsedTime = elapsedTimes.retryUntil(_.value >= loggingThreshold.value).generateOne
Expand All @@ -209,12 +208,11 @@ class ExecutionTimeRecorderSpec
(elapsedTime -> blockOut)
.pure[IO]
.flatMap(logExecutionTime(blockExecutionMessage))
.unsafeRunSync() shouldBe blockOut

logger.loggedOnly(Warn(s"$blockExecutionMessage in ${elapsedTime}ms"))
.asserting(_ shouldBe blockOut) >>
IO(logger.loggedOnly(Warn(s"$blockExecutionMessage in ${elapsedTime}ms")))
}

"not log a message if the elapsed time is < threshold" in new TestCase {
"not log a message if the elapsed time is < threshold" in {
import executionTimeRecorder._

val elapsedTime = ElapsedTime(loggingThreshold.value - 1)
Expand All @@ -224,47 +222,47 @@ class ExecutionTimeRecorderSpec
(elapsedTime -> blockOut)
.pure[IO]
.flatMap(logExecutionTime(blockExecutionMessage))
.unsafeRunSync() shouldBe blockOut

logger.expectNoLogs()
.asserting(_ shouldBe blockOut) >>
IO(logger.expectNoLogs())
}
}

"apply" should {

"read the logging threshold from 'logging.elapsed-time-threshold' and instantiate the recorder with it" in {
forAll(finiteDuration retryUntil (_.toMillis > 0)) { threshold =>
val config = ConfigFactory.parseMap(
Map(
"logging" -> Map(
"elapsed-time-threshold" -> threshold.toString()
).asJava
).asJava
)

implicit val logger: TestLogger[IO] = TestLogger[IO]()
val executionTimeRecorder = ExecutionTimeRecorder[IO](config).unsafeRunSync()
val threshold = finiteDuration.retryUntil(_.toMillis > 0).generateOne
val config = ConfigFactory.parseMap(
Map(
"logging" -> Map(
"elapsed-time-threshold" -> threshold.toString
).asJava
).asJava
)

val elapsedTime = ElapsedTime(threshold.toMillis)
val blockOut = nonEmptyStrings().generateOne
val blockExecutionMessage = "block executed"
implicit val logger: TestLogger[IO] = TestLogger[IO]()
val executionTimeRecorder = ExecutionTimeRecorder[IO](config).unsafeRunSync()

(elapsedTime -> blockOut)
.pure[IO]
.flatMap(executionTimeRecorder.logExecutionTimeWhen { case _ => blockExecutionMessage })
.unsafeRunSync() shouldBe blockOut
val elapsedTime = ElapsedTime(threshold.toMillis)
val blockOut = nonEmptyStrings().generateOne
val blockExecutionMessage = "block executed"

logger.loggedOnly(Warn(s"$blockExecutionMessage in ${elapsedTime}ms"))
}
(elapsedTime -> blockOut)
.pure[IO]
.flatMap(executionTimeRecorder.logExecutionTimeWhen { case _ => blockExecutionMessage })
.asserting(_ shouldBe blockOut) >>
IO(logger.loggedOnly(Warn(s"$blockExecutionMessage in ${elapsedTime}ms")))
}
}

private trait TestCase {
private lazy val block = mockFunction[IO[String]]

val block = mockFunction[IO[String]]
private lazy val loggingThreshold = ElapsedTime(1000 millis)
private implicit lazy val logger: TestLogger[IO] = TestLogger[IO]()
private lazy val executionTimeRecorder = new ExecutionTimeRecorderImpl[IO](loggingThreshold, maybeHistogram = None)

val loggingThreshold = ElapsedTime(1000 millis)
implicit val logger: TestLogger[IO] = TestLogger[IO]()
val executionTimeRecorder = new ExecutionTimeRecorderImpl[IO](loggingThreshold, maybeHistogram = None)
protected override def beforeEach() = {
super.beforeEach()
logger.reset()
}
}
2 changes: 1 addition & 1 deletion ...r/src/main/scala/io/renku/triplesgenerator/events/consumers/membersync/EventHandler.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -53,7 +53,7 @@ private class EventHandler[F[_]: MonadCancelThrow: Logger](
override def createHandlingDefinition(): EventHandlingDefinition =
EventHandlingDefinition(
decode = _.event.getProjectSlug,
process = (tsWriteLock: Lock[F, projects.Slug]).surround[Unit](synchronizeMembers _),
process = (tsWriteLock: Lock[F, projects.Slug]).surround[Unit](synchronizeMembers(_)),
precondition = verifyTSReady,
onRelease = subscriptionMechanism.renewSubscription().some
)
Expand Down
Loading