Fix timing metric value different from span duration (#3368)

* removed timing from IMetricsAggregator
* duration of timing metric of MetricsApi now equals span duration
* local metrics aggregator is fetch directly from the span in the timing api

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

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 {

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<String, String> tags,
-      final @Nullable LocalMetricsAggregator localMetricsAggregator);
-
   void flush(boolean force);
 }

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<String, String> 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,

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<String, String> 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<String, String> 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);
     }
   }
 }

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<String, String> tags,
-      final @Nullable LocalMetricsAggregator localMetricsAggregator) {
-    callback.run();
-  }
-
   @Override
   public void flush(final boolean force) {
     // no-op

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)
             }
         )
     }

sentry/src/test/java/io/sentry/metrics/MetricsApiTest.kt

@@ -1,15 +1,18 @@
 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
 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<String, String> = emptyMap(),
-            spanProvider: () -> ISpan? = { mock<ISpan>() }
+            spanProvider: () -> ISpan? = {
+                val span = mock<ISpan>()
+                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<LocalMetricsAggregator>()
         val span = mock<ISpan>()
-        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