diff --git a/CHANGELOG.md b/CHANGELOG.md index 3b1eb550a1..34b429a9c4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,11 @@ # Changelog +## Unreleased + +### Fixes + +- Fix timing metric value different from span duration ([#3368](https://github.com/getsentry/sentry-java/pull/3368)) + ## 7.8.0 ### Features diff --git a/sentry/api/sentry.api b/sentry/api/sentry.api index 5269ae3c5a..84fa3a4751 100644 --- a/sentry/api/sentry.api +++ b/sentry/api/sentry.api @@ -634,7 +634,6 @@ public abstract interface class io/sentry/IMetricsAggregator : java/io/Closeable public abstract fun increment (Ljava/lang/String;DLio/sentry/MeasurementUnit;Ljava/util/Map;JLio/sentry/metrics/LocalMetricsAggregator;)V public abstract fun set (Ljava/lang/String;ILio/sentry/MeasurementUnit;Ljava/util/Map;JLio/sentry/metrics/LocalMetricsAggregator;)V public abstract fun set (Ljava/lang/String;Ljava/lang/String;Lio/sentry/MeasurementUnit;Ljava/util/Map;JLio/sentry/metrics/LocalMetricsAggregator;)V - public abstract fun timing (Ljava/lang/String;Ljava/lang/Runnable;Lio/sentry/MeasurementUnit$Duration;Ljava/util/Map;Lio/sentry/metrics/LocalMetricsAggregator;)V } public abstract interface class io/sentry/IOptionsObserver { @@ -1039,7 +1038,6 @@ public final class io/sentry/MetricsAggregator : io/sentry/IMetricsAggregator, j public fun run ()V public fun set (Ljava/lang/String;ILio/sentry/MeasurementUnit;Ljava/util/Map;JLio/sentry/metrics/LocalMetricsAggregator;)V public fun set (Ljava/lang/String;Ljava/lang/String;Lio/sentry/MeasurementUnit;Ljava/util/Map;JLio/sentry/metrics/LocalMetricsAggregator;)V - public fun timing (Ljava/lang/String;Ljava/lang/Runnable;Lio/sentry/MeasurementUnit$Duration;Ljava/util/Map;Lio/sentry/metrics/LocalMetricsAggregator;)V } public final class io/sentry/MonitorConfig : io/sentry/JsonSerializable, io/sentry/JsonUnknown { @@ -3561,7 +3559,6 @@ public final class io/sentry/metrics/NoopMetricsAggregator : io/sentry/IMetricsA public fun set (Ljava/lang/String;ILio/sentry/MeasurementUnit;Ljava/util/Map;JLio/sentry/metrics/LocalMetricsAggregator;)V public fun set (Ljava/lang/String;Ljava/lang/String;Lio/sentry/MeasurementUnit;Ljava/util/Map;JLio/sentry/metrics/LocalMetricsAggregator;)V public fun startSpanForMetric (Ljava/lang/String;Ljava/lang/String;)Lio/sentry/ISpan; - public fun timing (Ljava/lang/String;Ljava/lang/Runnable;Lio/sentry/MeasurementUnit$Duration;Ljava/util/Map;Lio/sentry/metrics/LocalMetricsAggregator;)V } public final class io/sentry/metrics/SetMetric : io/sentry/metrics/Metric { diff --git a/sentry/src/main/java/io/sentry/IMetricsAggregator.java b/sentry/src/main/java/io/sentry/IMetricsAggregator.java index 41228c137d..0968c4f33c 100644 --- a/sentry/src/main/java/io/sentry/IMetricsAggregator.java +++ b/sentry/src/main/java/io/sentry/IMetricsAggregator.java @@ -103,21 +103,5 @@ void set( final long timestampMs, final @Nullable LocalMetricsAggregator localMetricsAggregator); - /** - * Emits a distribution with the time it takes to run a given code block. - * - * @param key A unique key identifying the metric - * @param callback The code block to measure - * @param unit An optional unit, see {@link MeasurementUnit.Duration}, defaults to seconds - * @param tags Optional Tags to associate with the metric - * @param localMetricsAggregator The local metrics aggregator for creating span summaries - */ - void timing( - final @NotNull String key, - final @NotNull Runnable callback, - final @NotNull MeasurementUnit.Duration unit, - final @Nullable Map tags, - final @Nullable LocalMetricsAggregator localMetricsAggregator); - void flush(boolean force); } diff --git a/sentry/src/main/java/io/sentry/MetricsAggregator.java b/sentry/src/main/java/io/sentry/MetricsAggregator.java index b9383ac865..9d5f277477 100644 --- a/sentry/src/main/java/io/sentry/MetricsAggregator.java +++ b/sentry/src/main/java/io/sentry/MetricsAggregator.java @@ -141,24 +141,6 @@ public void set( add(MetricType.Set, key, intValue, unit, tags, timestampMs, localMetricsAggregator); } - @Override - public void timing( - final @NotNull String key, - final @NotNull Runnable callback, - final @NotNull MeasurementUnit.Duration unit, - final @Nullable Map tags, - final @Nullable LocalMetricsAggregator localMetricsAggregator) { - final long startMs = nowMillis(); - final long startNanos = System.nanoTime(); - try { - callback.run(); - } finally { - final long durationNanos = (System.nanoTime() - startNanos); - final double value = MetricsHelper.convertNanosTo(unit, durationNanos); - add(MetricType.Distribution, key, value, unit, tags, startMs, localMetricsAggregator); - } - } - @SuppressWarnings({"FutureReturnValueIgnored", "UnusedVariable"}) private void add( final @NotNull MetricType type, diff --git a/sentry/src/main/java/io/sentry/metrics/MetricsApi.java b/sentry/src/main/java/io/sentry/metrics/MetricsApi.java index 0d90c278b2..45273d6885 100644 --- a/sentry/src/main/java/io/sentry/metrics/MetricsApi.java +++ b/sentry/src/main/java/io/sentry/metrics/MetricsApi.java @@ -3,6 +3,8 @@ import io.sentry.IMetricsAggregator; import io.sentry.ISpan; import io.sentry.MeasurementUnit; +import io.sentry.SentryDate; +import io.sentry.SentryNanotimeDate; import java.util.Map; import org.jetbrains.annotations.ApiStatus; import org.jetbrains.annotations.NotNull; @@ -425,23 +427,38 @@ public void timing( unit != null ? unit : MeasurementUnit.Duration.SECOND; final @NotNull Map enrichedTags = MetricsHelper.mergeTags(tags, aggregator.getDefaultTagsForMetrics()); - final @Nullable LocalMetricsAggregator localMetricsAggregator = - aggregator.getLocalMetricsAggregator(); + final @Nullable LocalMetricsAggregator localMetricsAggregator; final @Nullable ISpan span = aggregator.startSpanForMetric("metric.timing", key); + // If the span was started, we take its local aggregator, otherwise we request another one. + localMetricsAggregator = + span != null ? span.getLocalMetricsAggregator() : aggregator.getLocalMetricsAggregator(); + if (span != null && tags != null) { for (final @NotNull Map.Entry entry : tags.entrySet()) { span.setTag(entry.getKey(), entry.getValue()); } } + final long timestamp = System.currentTimeMillis(); + final long startNanos = System.nanoTime(); try { - aggregator - .getMetricsAggregator() - .timing(key, callback, durationUnit, enrichedTags, localMetricsAggregator); + callback.run(); } finally { + // If we have a span, the duration we emit is the same of the span, otherwise calculate it. + final long durationNanos; if (span != null) { span.finish(); + // We finish the span, so we should have a finish date, but it's still nullable. + final @NotNull SentryDate spanFinishDate = + span.getFinishDate() != null ? span.getFinishDate() : new SentryNanotimeDate(); + durationNanos = spanFinishDate.diff(span.getStartDate()); + } else { + durationNanos = System.nanoTime() - startNanos; } + final double value = MetricsHelper.convertNanosTo(durationUnit, durationNanos); + aggregator + .getMetricsAggregator() + .distribution(key, value, durationUnit, enrichedTags, timestamp, localMetricsAggregator); } } } diff --git a/sentry/src/main/java/io/sentry/metrics/NoopMetricsAggregator.java b/sentry/src/main/java/io/sentry/metrics/NoopMetricsAggregator.java index 8e917006d2..f9038062b5 100644 --- a/sentry/src/main/java/io/sentry/metrics/NoopMetricsAggregator.java +++ b/sentry/src/main/java/io/sentry/metrics/NoopMetricsAggregator.java @@ -75,16 +75,6 @@ public void set( // no-op } - @Override - public void timing( - final @NotNull String key, - final @NotNull Runnable callback, - final @NotNull MeasurementUnit.Duration unit, - final @Nullable Map tags, - final @Nullable LocalMetricsAggregator localMetricsAggregator) { - callback.run(); - } - @Override public void flush(final boolean force) { // no-op diff --git a/sentry/src/test/java/io/sentry/MetricsAggregatorTest.kt b/sentry/src/test/java/io/sentry/MetricsAggregatorTest.kt index bd131bb4fa..e757a52d61 100644 --- a/sentry/src/test/java/io/sentry/MetricsAggregatorTest.kt +++ b/sentry/src/test/java/io/sentry/MetricsAggregatorTest.kt @@ -268,21 +268,12 @@ class MetricsAggregatorTest { 20_001, null ) - aggregator.timing( - "name0", - { - Thread.sleep(2) - }, - MeasurementUnit.Duration.SECOND, - mapOf("key0" to "value0"), - null - ) aggregator.flush(true) verify(fixture.client).captureMetrics( check { val metrics = MetricsHelperTest.parseMetrics(it.encodeToStatsd()) - assertEquals(6, metrics.size) + assertEquals(5, metrics.size) } ) } diff --git a/sentry/src/test/java/io/sentry/metrics/MetricsApiTest.kt b/sentry/src/test/java/io/sentry/metrics/MetricsApiTest.kt index 359563f78a..24ef6ffa5b 100644 --- a/sentry/src/test/java/io/sentry/metrics/MetricsApiTest.kt +++ b/sentry/src/test/java/io/sentry/metrics/MetricsApiTest.kt @@ -1,8 +1,10 @@ package io.sentry.metrics +import io.sentry.DateUtils import io.sentry.IMetricsAggregator import io.sentry.ISpan import io.sentry.MeasurementUnit +import io.sentry.SentryNanotimeDate import io.sentry.metrics.MetricsApi.IMetricsInterface import org.mockito.kotlin.any import org.mockito.kotlin.anyOrNull @@ -10,6 +12,7 @@ import org.mockito.kotlin.eq import org.mockito.kotlin.mock import org.mockito.kotlin.never import org.mockito.kotlin.verify +import org.mockito.kotlin.whenever import kotlin.test.Test import kotlin.test.assertEquals @@ -25,7 +28,12 @@ class MetricsApiTest { fun getSut( defaultTags: Map = emptyMap(), - spanProvider: () -> ISpan? = { mock() } + spanProvider: () -> ISpan? = { + val span = mock() + val date = SentryNanotimeDate() + whenever(span.startDate).thenReturn(date) + span + } ): MetricsApi { val localAggregator = localMetricsAggregator @@ -280,12 +288,14 @@ class MetricsApiTest { api.timing("timing") { // no-op } - verify(fixture.aggregator).timing( + val spanLocalAggregator = fixture.lastSpan!!.localMetricsAggregator + verify(fixture.aggregator).distribution( anyOrNull(), anyOrNull(), anyOrNull(), anyOrNull(), - eq(fixture.localMetricsAggregator) + anyOrNull(), + eq(spanLocalAggregator) ) } @@ -304,16 +314,37 @@ class MetricsApiTest { } @Test - fun `timing applies metric tags as span tags`() { + fun `timing value equals span duration`() { + val startDate = SentryNanotimeDate() + val finishNanos = startDate.nanoTimestamp() + 10000 + val finishDate = SentryNanotimeDate(DateUtils.nanosToDate(finishNanos), finishNanos) + val localAggregator = mock() val span = mock() - val api = fixture.getSut( - spanProvider = { - span - }, - defaultTags = mapOf( - "release" to "1.0" - ) + whenever(span.startDate).thenReturn(startDate) + whenever(span.finishDate).thenReturn(finishDate) + whenever(span.localMetricsAggregator).thenReturn(localAggregator) + + val api = fixture.getSut(spanProvider = { span }) + + api.timing("key") { + // no-op + } + + assertEquals("metric.timing", fixture.lastOp) + assertEquals("key", fixture.lastDescription) + verify(fixture.aggregator).distribution( + eq("key"), + eq((finishDate.diff(startDate)) / 1000000000.0), + eq(MeasurementUnit.Duration.SECOND), + anyOrNull(), + anyOrNull(), + eq(localAggregator) ) + } + + @Test + fun `timing applies metric tags as span tags`() { + val api = fixture.getSut(defaultTags = mapOf("release" to "1.0")) // when timing is called api.timing("key", { // no-op