From fecdce87a5c8844c83b0ddd50f63aaf5eca38370 Mon Sep 17 00:00:00 2001 From: Mikhail Sokolov Date: Fri, 30 Aug 2024 16:44:16 +0300 Subject: [PATCH] Migrate to nanoTime for time* methods, improve API DX timeFunc and timeFuture used millisecond precision, which lead to issues like Summary quantiles being skewed towards 0 if measured latencies are close to 1 ms. To fix that: - time* methods use System.nanoTime() now - deprecate specific time*Nano methods, millisecond precision shouldn't be a choice to avoid mistakes - improve method naming, document all time-related public functionality - deprecate unused TemporalOps implicit conversion - overall developer experience improvements This change breaks source compatibility for some usages, but binary compatibility is preserved. --- build.sbt | 2 + .../prometheus/ClockPlatform.scala | 14 ++ .../prometheus/HasObserve.scala | 11 +- .../prometheus/ObserveDuration.scala | 201 ++++++++++++++---- .../prometheus/PrometheusHelper.scala | 55 ++++- .../prometheus/ObserveDurationSpec.scala | 130 ++++++++--- .../prometheus/PrometheusHelperSpec.scala | 31 +++ 7 files changed, 368 insertions(+), 76 deletions(-) create mode 100644 src/test/scala/com/evolutiongaming/prometheus/PrometheusHelperSpec.scala diff --git a/build.sbt b/build.sbt index 8dce469..74d04a5 100644 --- a/build.sbt +++ b/build.sbt @@ -28,6 +28,8 @@ Compile / doc / scalacOptions ++= Seq("-groups", "-implicits", "-no-link-warning publishTo := Some(Resolver.evolutionReleases) libraryDependencies ++= Seq( + // executor-tools dependency is not used anymore, left as is so MiMa bincompat report doesn't complain + // TODO: remove in 2.x "com.evolutiongaming" %% "executor-tools" % "1.0.4", "io.prometheus" % "simpleclient_common" % "0.8.1", "org.scalameta" %% "munit" % "1.0.0" % Test diff --git a/src/main/scala/com/evolutiongaming/prometheus/ClockPlatform.scala b/src/main/scala/com/evolutiongaming/prometheus/ClockPlatform.scala index 41539ee..5610339 100644 --- a/src/main/scala/com/evolutiongaming/prometheus/ClockPlatform.scala +++ b/src/main/scala/com/evolutiongaming/prometheus/ClockPlatform.scala @@ -1,14 +1,28 @@ package com.evolutiongaming.prometheus +/** Exposes platform time measuring capabilities needed for metrics + */ trait ClockPlatform { + + /** @see + * [[System#currentTimeMillis()]] + */ def nowMillis: Long + + /** @see + * [[System#nanoTime()]] + */ def nowNano: Long } object ClockPlatform { + /** Global singleton instance for default [[ClockPlatform]] for JVM + */ val default: ClockPlatform = new Default + /** Default [[ClockPlatform]] impl for JVM - use [[ClockPlatform.default]] global singleton instance! + */ class Default extends ClockPlatform { override def nowMillis: Long = System.currentTimeMillis() override def nowNano: Long = System.nanoTime() diff --git a/src/main/scala/com/evolutiongaming/prometheus/HasObserve.scala b/src/main/scala/com/evolutiongaming/prometheus/HasObserve.scala index 1f85e77..8481a5e 100644 --- a/src/main/scala/com/evolutiongaming/prometheus/HasObserve.scala +++ b/src/main/scala/com/evolutiongaming/prometheus/HasObserve.scala @@ -1,9 +1,16 @@ package com.evolutiongaming.prometheus +/** A type-class abstracting over prometheus client histogram-like classes providing "observe a Double value" method. + * + * Check [[PrometheusHelper]] for available implicit instances. + */ trait HasObserve[F] { - def observe(observer: F, duration: Double): Unit + + /** Observe a new sample value on a histogram-like metric type + */ + def observe(observer: F, value: Double): Unit } object HasObserve { - def apply[F](implicit hasObserve: HasObserve[F]) = hasObserve + def apply[F](implicit hasObserve: HasObserve[F]): HasObserve[F] = hasObserve } diff --git a/src/main/scala/com/evolutiongaming/prometheus/ObserveDuration.scala b/src/main/scala/com/evolutiongaming/prometheus/ObserveDuration.scala index 324538d..8d5742f 100644 --- a/src/main/scala/com/evolutiongaming/prometheus/ObserveDuration.scala +++ b/src/main/scala/com/evolutiongaming/prometheus/ObserveDuration.scala @@ -1,65 +1,184 @@ package com.evolutiongaming.prometheus -import io.prometheus.client.Collector +import io.prometheus.client.{Collector, SimpleTimer} +import scala.annotation.{nowarn, unused} import scala.concurrent.{ExecutionContext, Future} - -trait ObserveDuration[F] { - +import scala.math.Numeric.Implicits.* +import scala.util.Try + +/** Time duration measurement syntax for [[HasObserve]]-kind metrics from the prometheus client, i.e., Summary, Histogram. + * + * Here time is always reported in seconds, which means your prometheus metric name should end in `_seconds`. + * + * The class is not supposed to be used directly but as an implicit syntax provided by [[PrometheusHelper]]. + */ +sealed trait ObserveDuration[F] { + + /** Measures evaluation time of a block in seconds with nano-time precision + */ def timeFunc[T](f: => T): T - def timeFuncNanos[T](f: => T): T + /** Measures evaluation time of a block in seconds with nano-time precision + * + * @deprecated + * since 1.1.0 timeFunc has been changed to use nano-time precision, this method is obsolete and will be removed + */ + @deprecated( + message = "use timeFunc instead - it has nano-time precision now", + since = "1.1.0" + ) + def timeFuncNanos[T](f: => T): T = timeFunc(f) + + /** Measures evaluation time of an asynchronous block in seconds with nano-time precision + */ def timeFuture[T](f: => Future[T]): Future[T] - def timeFutureNanos[T](f: => Future[T]): Future[T] + /** Measures evaluation time of an asynchronous block in seconds with nano-time precision + * + * @deprecated + * since 1.1.0 timeFuture has been changed to use nano-time precision, this method is obsolete and will be removed + */ + @deprecated( + message = "use timeFuture instead - it has nano-time precision now", + since = "1.1.0" + ) + def timeFutureNanos[T](f: => Future[T]): Future[T] = timeFuture(f) + + /** Measures in seconds the time spent since the provided start time obtained using [[ClockPlatform.nowMillis]] + * + * @param start + * start time from a millisecond-precision clock + * @deprecated + * since 1.1.0, use timeTillNowMillis(: Long) with a primitive arg type and explicit precision name suffix + */ + @deprecated( + message = "use timeTillNowMillis(: Long) with a primitive arg type and explicit precision name suffix", + since = "1.1.0" + ) def timeTillNow[T](start: T)(implicit numeric: Numeric[T]): Unit + + /** Measures in seconds the time spent since the provided start time obtained using [[ClockPlatform.nowNano]] + * + * @param start + * start time from a nanosecond-precision clock + * @deprecated + * since 1.1.0, use timeTillNowNanos(: Long) with a primitive arg type + */ + @deprecated( + message = "use timeTillNowNanos(: Long) with a primitive arg type", + since = "1.1.0" + ) def timeTillNowNanos[T](start: T)(implicit numeric: Numeric[T]): Unit -} -object ObserveDuration { - def apply[F](implicit observeDuration: ObserveDuration[F]): ObserveDuration[F] = observeDuration + /** Measures in seconds the time spent since the provided start time obtained using [[ClockPlatform.nowMillis]] + */ + def timeTillNowMillis(startMs: Long): Unit = { + // default impl for a new method of a trait - added for keeping binary compatibility + // TODO: bincompat leftover, remove in 2.x - def fromHasObserver[F](observer: F)(implicit hasObserve: HasObserve[F], clock: ClockPlatform, ec: ExecutionContext): ObserveDuration[F] = - new ObserveDuration[F] { + timeTillNow[Long](startMs): @nowarn("cat=deprecation") + } - override def timeFunc[T](f: => T): T = - measureFunction(f, clock.nowMillis, timeTillNow[Long]) + /** Measures in seconds the time spent since the provided start time obtained using [[ClockPlatform.nowNano]] + */ + def timeTillNowNanos(startNs: Long): Unit = { + // default impl for a new method of a trait - added for keeping binary compatibility + // TODO: bincompat leftover, remove in 2.x - override def timeFuncNanos[T](f: => T): T = - measureFunction(f, clock.nowNano, timeTillNowNanos[Long]) + timeTillNowNanos[Long](startNs): @nowarn("cat=deprecation") + } +} - private def measureFunction[A](f: => A, start: Long, measurer: Long => Unit): A = - try f - finally measurer(start) +object ObserveDuration { + def apply[F](implicit observeDuration: ObserveDuration[F]): ObserveDuration[F] = observeDuration - override def timeFuture[T](f: => Future[T]): Future[T] = - measureFuture(f, clock.nowMillis, timeTillNow[Long]) + // TODO: bincompat leftover, remove in 2.x + @deprecated( + message = "use create", + since = "1.1.0" + ) + def fromHasObserver[F]( + observer: F + )(implicit + hasObserve: HasObserve[F], + clock: ClockPlatform, + @unused ec: ExecutionContext + ): ObserveDuration[F] = new ObserveDurationImpl[F](observer) + + /** Creates [[ObserveDuration]] implementation instance + * + * @param observer + * metric instance which has [[HasObserve]] + * @param hasObserve + * [[HasObserve]] instance for the metric + * @param clock + * [[ClockPlatform]] to use for time measurement + * @tparam F + * metric type + */ + def create[F]( + observer: F + )(implicit + hasObserve: HasObserve[F], + clock: ClockPlatform + ): ObserveDuration[F] = new ObserveDurationImpl[F](observer) + + private final class ObserveDurationImpl[F]( + observer: F + )(implicit + hasObserve: HasObserve[F], + clock: ClockPlatform + ) extends ObserveDuration[F] { + + override def timeFunc[T](f: => T): T = { + val startNs = clock.nowNano + try { + f + } finally { + timeTillNowNanos(startNs) + } + } - override def timeFutureNanos[T](f: => Future[T]): Future[T] = - measureFuture(f, clock.nowNano, timeTillNowNanos[Long]) + override def timeFuture[T](f: => Future[T]): Future[T] = { + val startNs = clock.nowNano + Future + .fromTry(Try { + f + }) + .flatten + .andThen { case _ => + timeTillNowNanos(startNs) + }(ExecutionContext.parasitic) + } - private def measureFuture[A]( - f: => Future[A], - start: Long, - measurer: Long => Unit - )(implicit ec: ExecutionContext): Future[A] = f andThen { case _ => measurer(start) } + override def timeTillNow[T]( + start: T + )(implicit numeric: Numeric[T]): Unit = { + val value = duration(start, clock.nowMillis) / Collector.MILLISECONDS_PER_SECOND + hasObserve.observe(observer, value) + } - override def timeTillNow[T]( - start: T - )(implicit numeric: Numeric[T]): Unit = { - val value = duration(start, clock.nowMillis) / Collector.MILLISECONDS_PER_SECOND - hasObserve.observe(observer, value) - } + override def timeTillNowNanos[T](start: T)(implicit + numeric: Numeric[T] + ): Unit = { + val value = duration(start, clock.nowNano) / Collector.NANOSECONDS_PER_SECOND + hasObserve.observe(observer, value) + } - override def timeTillNowNanos[T](start: T)(implicit - numeric: Numeric[T] - ): Unit = { - val value = duration(start, clock.nowNano) / Collector.NANOSECONDS_PER_SECOND - hasObserve.observe(observer, value) - } + override def timeTillNowMillis(startMs: Long): Unit = { + val endMs = clock.nowMillis + val elapsedSeconds = (endMs - startMs).toDouble / Collector.MILLISECONDS_PER_SECOND + hasObserve.observe(observer, elapsedSeconds) } - private def duration[A](start: A, now: Long)(implicit a: Numeric[A]): Double = { - now.toDouble - a.toDouble(start) + override def timeTillNowNanos(startNs: Long): Unit = { + val endNs = clock.nowNano + hasObserve.observe(observer, SimpleTimer.elapsedSecondsFromNanos(startNs, endNs)) + } + } + + private def duration[A: Numeric](start: A, now: Long): Double = { + now.toDouble - start.toDouble } } diff --git a/src/main/scala/com/evolutiongaming/prometheus/PrometheusHelper.scala b/src/main/scala/com/evolutiongaming/prometheus/PrometheusHelper.scala index 1abbda7..92e8da0 100644 --- a/src/main/scala/com/evolutiongaming/prometheus/PrometheusHelper.scala +++ b/src/main/scala/com/evolutiongaming/prometheus/PrometheusHelper.scala @@ -1,12 +1,21 @@ package com.evolutiongaming.prometheus -import com.evolutiongaming.concurrent.CurrentThreadExecutionContext import io.prometheus.client.{Gauge, Histogram, SimpleCollector, Summary} -import scala.concurrent.{ExecutionContext, Future} - +import scala.concurrent.Future +import scala.math.Numeric.Implicits.* + +/** Main entry point for prometheus-tools goodies, mainly extension method for prometheus client classes. + * + * Usage: + * {{{ + * import com.evolutiongaming.prometheus.PrometheusHelper.* + * }}} + * + * @see + * [[ObserveDuration]] + */ object PrometheusHelper { - private implicit val ec: ExecutionContext = CurrentThreadExecutionContext private implicit val clock: ClockPlatform = ClockPlatform.default implicit val histogramObs: HasObserve[Histogram] = (histogram: Histogram, duration: Double) => histogram.observe(duration) @@ -19,15 +28,42 @@ object PrometheusHelper { implicit class GaugeOps(val gauge: Gauge) extends AnyVal { - def collect[T](f: => T)(implicit numeric: Numeric[T]): Gauge = { + def collect[T: Numeric](f: => T): Gauge = { val child = new Gauge.Child() { - override def get() = numeric.toDouble(f) + override def get(): Double = f.toDouble } gauge.setChild(child) } } - implicit class TemporalOps[A: ObserveDuration](val a: A) { + /* + TODO: bincompat leftover, remove in 2.x + + Without this magic method MiMa complained: + static method TemporalOps(java.lang.Object,com.evolutiongaming.prometheus.ObserveDuration)com.evolutiongaming.prometheus.PrometheusHelper#TemporalOps + in class com.evolutiongaming.prometheus.PrometheusHelper does not have a correspondent in current version + + The visibility also has to be public, otherwise scalac does not reliably generate static method for both 2.13 and 3 + */ + @deprecated( + message = "referencing TemporalOps directly is deprecated, use implicit syntax", + since = "1.1.0" + ) + def TemporalOps[A]( + v1: A, + v2: com.evolutiongaming.prometheus.ObserveDuration[A] + ): com.evolutiongaming.prometheus.PrometheusHelper.TemporalOps[A] = new TemporalOps[A](v1)(v2) + + /* + TODO: bincompat leftover, remove in 2.x + + TemporalOps wasn't needed to provide ObserveDuration syntax, should be removed - see PrometheusHelperSpec + */ + @deprecated( + message = "referencing TemporalOps directly is deprecated, use implicit syntax", + since = "1.1.0" + ) + private[prometheus] class TemporalOps[A: ObserveDuration](val a: A) { def timeFunc[T](f: => T): T = ObserveDuration[A].timeFunc(f) @@ -46,7 +82,7 @@ object PrometheusHelper { ObserveDuration[A].timeTillNowNanos(start) } - implicit class BuilderOps[C <: SimpleCollector[_], B <: SimpleCollector.Builder[ + implicit class BuilderOps[C <: SimpleCollector[?], B <: SimpleCollector.Builder[ B, C ]](val self: B) @@ -60,7 +96,8 @@ object PrometheusHelper { } } - implicit def observeDuration[F](observer: F)(implicit hasObserve: HasObserve[F]): ObserveDuration[F] = ObserveDuration.fromHasObserver(observer) + implicit def observeDuration[F](observer: F)(implicit hasObserve: HasObserve[F]): ObserveDuration[F] = + ObserveDuration.create(observer) implicit class RichSummaryBuilder(val summaryBuilder: Summary.Builder) extends AnyVal { diff --git a/src/test/scala/com/evolutiongaming/prometheus/ObserveDurationSpec.scala b/src/test/scala/com/evolutiongaming/prometheus/ObserveDurationSpec.scala index e4a32f9..a890123 100644 --- a/src/test/scala/com/evolutiongaming/prometheus/ObserveDurationSpec.scala +++ b/src/test/scala/com/evolutiongaming/prometheus/ObserveDurationSpec.scala @@ -1,47 +1,129 @@ package com.evolutiongaming.prometheus -import com.evolutiongaming.concurrent.CurrentThreadExecutionContext import io.prometheus.client.Collector -import scala.concurrent.ExecutionContext +import scala.collection.mutable +import scala.concurrent.{ExecutionContext, Future, Promise} +import scala.util.Success class ObserveDurationSpec extends munit.FunSuite with munit.Assertions { - private implicit val ec: ExecutionContext = CurrentThreadExecutionContext + private val TenthOfNsInSec: Double = nsToSec(1L) / 10 - def cmp(x: Double, y: Double): Boolean = Math.abs(x - y) <= 0.000000001 + test("timeTillNowMillis should correctly convert duration into double") { + val durMs = 667L - def testClockPlatform(v: Long) = new ClockPlatform { - override def nowMillis: Long = v - override def nowNano: Long = v + implicit val hasObserve: TestHasObserve = new TestHasObserve + implicit val clock: ClockPlatform = testConstMillisClock(durMs) + + val observeDuration = ObserveDuration.create(()) + + observeDuration.timeTillNowMillis(startMs = 0L) + + hasObserve.verifyObserved(msToSec(durMs)) + } + + test("timeTillNowNanos should correctly convert duration into double") { + val durNs = 730598L + + implicit val hasObserve: TestHasObserve = new TestHasObserve + implicit val clock: ClockPlatform = testConstNanosClock(durNs) + + val observeDuration = ObserveDuration.create(()) + + observeDuration.timeTillNowNanos(startNs = 0L) + + hasObserve.verifyObserved(nsToSec(durNs)) } - def testHasObserver(expected: Double) = new HasObserve[Unit] { + test("timeFunc should measure time with nanosecond precision") { + val startTimeNs = 12345L + val durNs = 1000L + + implicit val hasObserve: TestHasObserve = new TestHasObserve + implicit val clock: TestNanoClock = new TestNanoClock(initialValue = startTimeNs) + + val impl = ObserveDuration.create(()) + + impl.timeFunc { + clock.advanceClock(durNs) + } + + hasObserve.verifyObserved(nsToSec(durNs)) + } + + test("timeFuture should measure time with nanosecond precision") { + val durNs = 1L + + implicit val hasObserve: TestHasObserve = new TestHasObserve + implicit val clock: TestNanoClock = new TestNanoClock() + + val observeDuration = ObserveDuration.create(()) - override def observe(observer: Unit, duration: Double): Unit = { - assert(cmp(expected, duration), clue = s"Expected duration $expected did not match calculated $duration") + val finishPromise = Promise[Unit]() + + val resultF: Future[String] = observeDuration.timeFuture { + finishPromise.future.map { _ => + clock.advanceClock(durNs) + "result" + }(ExecutionContext.parasitic) } + + assert(!resultF.isCompleted) + hasObserve.verifyNothingObserved() + + finishPromise.success(()) + + assert(resultF.value.contains(Success("result"))) + hasObserve.verifyObserved(nsToSec(durNs)) + } + + private def testConstMillisClock(millis: Long): ClockPlatform = new ClockPlatform { + override def nowMillis: Long = millis + + override def nowNano: Long = ??? + } + + private def testConstNanosClock(nanos: Long): ClockPlatform = new ClockPlatform { + override def nowMillis: Long = ??? + + override def nowNano: Long = nanos } - test("TimeToNow should correctly convert duration into double") { - val expectedLong = 667L - val expectedDouble = expectedLong.toDouble / Collector.MILLISECONDS_PER_SECOND + private def nsToSec(nanos: Long): Double = nanos.toDouble / Collector.NANOSECONDS_PER_SECOND + + private def msToSec(nanos: Long): Double = nanos.toDouble / Collector.MILLISECONDS_PER_SECOND - implicit val hasObserve: HasObserve[Unit] = testHasObserver(expectedDouble) - implicit val clock: ClockPlatform = testClockPlatform(expectedLong) + private final class TestHasObserve extends HasObserve[Unit] { + private val observed: mutable.ArrayBuffer[Double] = mutable.ArrayBuffer.empty - val observeDuration = ObserveDuration.fromHasObserver(()) - observeDuration.timeTillNow(0L) + override def observe(observer: Unit, value: Double): Unit = { + observed += value + } + + def verifyObserved(value: Double): Unit = { + assert(observed.size == 1, s"only 1 value expected to be observed, got $observed") + assertEqualsDouble( + obtained = observed.head, + expected = value, + delta = TenthOfNsInSec + ) + } + + def verifyNothingObserved(): Unit = { + assert(observed.isEmpty, s"no values should be observed, got $observed") + } } - test("TimeToNowNano should correctly convert duration into double") { - val expectedLong = 730598L - val expectedDouble = expectedLong.toDouble / Collector.NANOSECONDS_PER_SECOND + private final class TestNanoClock(initialValue: Long = 12345L) extends ClockPlatform { + private var currentValue: Long = initialValue - implicit val hasObserve: HasObserve[Unit] = testHasObserver(expectedDouble) - implicit val clock: ClockPlatform = testClockPlatform(expectedLong) + override def nowMillis: Long = ??? - val observeDuration = ObserveDuration.fromHasObserver(()) - observeDuration.timeTillNowNanos(0L) + override def nowNano: Long = currentValue + + def advanceClock(nanos: Long): Unit = { + currentValue += nanos + } } } diff --git a/src/test/scala/com/evolutiongaming/prometheus/PrometheusHelperSpec.scala b/src/test/scala/com/evolutiongaming/prometheus/PrometheusHelperSpec.scala new file mode 100644 index 0000000..e3fe009 --- /dev/null +++ b/src/test/scala/com/evolutiongaming/prometheus/PrometheusHelperSpec.scala @@ -0,0 +1,31 @@ +package com.evolutiongaming.prometheus + +import scala.annotation.unused +import scala.concurrent.Future + +class PrometheusHelperSpec extends munit.FunSuite with munit.Assertions { + test("Provide ObserveDuration syntax for concrete HasObserve instances") { + /* + Smoke test verifying that PrometheusHelper implicits machinery still provides required ObserveDuration syntax. + Nothing is executed here, but the code has to compile. + */ + + import com.evolutiongaming.prometheus.PrometheusHelper.* + + @unused + def fun(s: io.prometheus.client.Summary): Unit = { + @unused + val syncRes: Double = s.timeFunc { + Thread.sleep(1000L) + 1d + } + + @unused + val futRes: Future[Int] = s.timeFuture { + Future.successful(1) + } + + () + } + } +}