diff --git a/sentry-micrometer/README.md b/sentry-micrometer/README.md index 018f2056a4..1adc22df90 100644 --- a/sentry-micrometer/README.md +++ b/sentry-micrometer/README.md @@ -40,10 +40,17 @@ Passive meters are polled every 60 seconds by default: | `LongTaskTimer` active tasks | `${name}.active` gauge | | `LongTaskTimer` active duration | `${name}.duration` gauge in milliseconds | | `FunctionCounter` | Positive counter delta | +| `FunctionTimer` count | `${name}.count` positive counter delta | +| `FunctionTimer` total time | `${name}.total_time` positive counter delta in milliseconds | -The first successful finite `FunctionCounter` poll establishes its baseline and emits nothing. -Later positive deltas are sent. A decreasing value is treated as a reset and establishes a new -baseline. +The first successful finite function-meter poll establishes its baseline and emits nothing. Later +positive deltas are sent. A decreasing value is treated as a reset and establishes a new baseline. +`FunctionTimer` tracks its count and total-time baselines independently. + +A `FunctionTimer` does not expose individual durations, so the integration emits neither a +mean gauge nor a distribution. To derive a correctly weighted mean across instances, divide the +sum of `${name}.total_time` by the sum of `${name}.count`. Percentiles cannot be derived from these +cumulative values. Unsupported custom meters remain readable through Micrometer but are not exported to Sentry. diff --git a/sentry-micrometer/src/main/java/io/sentry/micrometer/SentryFunctionTimer.java b/sentry-micrometer/src/main/java/io/sentry/micrometer/SentryFunctionTimer.java new file mode 100644 index 0000000000..acdf02f15c --- /dev/null +++ b/sentry-micrometer/src/main/java/io/sentry/micrometer/SentryFunctionTimer.java @@ -0,0 +1,82 @@ +package io.sentry.micrometer; + +import io.micrometer.core.instrument.Meter; +import io.micrometer.core.instrument.cumulative.CumulativeFunctionTimer; +import java.util.concurrent.TimeUnit; +import java.util.function.ToDoubleFunction; +import java.util.function.ToLongFunction; +import org.jetbrains.annotations.NotNull; + +final class SentryFunctionTimer extends CumulativeFunctionTimer { + private final @NotNull SentryMeterRegistry registry; + private final @NotNull SentryMetricInfo countMetricInfo; + private final @NotNull SentryMetricInfo totalTimeMetricInfo; + private volatile boolean removed; + private boolean countInitialized; + private double previousCount; + private boolean totalTimeInitialized; + private double previousTotalTime; + + SentryFunctionTimer( + final @NotNull Meter.Id id, + final @NotNull T obj, + final @NotNull ToLongFunction countFunction, + final @NotNull ToDoubleFunction totalTimeFunction, + final @NotNull TimeUnit totalTimeFunctionUnit, + final @NotNull TimeUnit baseTimeUnit, + final @NotNull SentryMeterRegistry registry, + final @NotNull SentryMetricInfo countMetricInfo, + final @NotNull SentryMetricInfo totalTimeMetricInfo) { + super(id, obj, countFunction, totalTimeFunction, totalTimeFunctionUnit, baseTimeUnit); + this.registry = registry; + this.countMetricInfo = countMetricInfo; + this.totalTimeMetricInfo = totalTimeMetricInfo; + } + + void poll() { + pollCount(); + pollTotalTime(); + } + + private void pollCount() { + final double currentCount = count(); + if (!Double.isFinite(currentCount) || removed || registry.isClosed()) { + return; + } + + if (!countInitialized || currentCount < previousCount) { + countInitialized = true; + previousCount = currentCount; + return; + } + + final double delta = currentCount - previousCount; + previousCount = currentCount; + if (delta > 0.0 && !removed) { + registry.captureCounter(countMetricInfo, delta); + } + } + + private void pollTotalTime() { + final double currentTotalTime = totalTime(TimeUnit.MILLISECONDS); + if (!Double.isFinite(currentTotalTime) || removed || registry.isClosed()) { + return; + } + + if (!totalTimeInitialized || currentTotalTime < previousTotalTime) { + totalTimeInitialized = true; + previousTotalTime = currentTotalTime; + return; + } + + final double delta = currentTotalTime - previousTotalTime; + previousTotalTime = currentTotalTime; + if (delta > 0.0 && !removed) { + registry.captureCounter(totalTimeMetricInfo, delta); + } + } + + void markRemoved() { + removed = true; + } +} diff --git a/sentry-micrometer/src/main/java/io/sentry/micrometer/SentryMeterRegistry.java b/sentry-micrometer/src/main/java/io/sentry/micrometer/SentryMeterRegistry.java index 068fed61f7..446c0b1be8 100644 --- a/sentry-micrometer/src/main/java/io/sentry/micrometer/SentryMeterRegistry.java +++ b/sentry-micrometer/src/main/java/io/sentry/micrometer/SentryMeterRegistry.java @@ -15,7 +15,6 @@ import io.micrometer.core.instrument.Tag; import io.micrometer.core.instrument.TimeGauge; import io.micrometer.core.instrument.Timer; -import io.micrometer.core.instrument.cumulative.CumulativeFunctionTimer; import io.micrometer.core.instrument.distribution.DistributionStatisticConfig; import io.micrometer.core.instrument.distribution.pause.PauseDetector; import io.micrometer.core.instrument.internal.DefaultGauge; @@ -140,8 +139,16 @@ public SentryMeterRegistry(final long pollIntervalMillis) { final @NotNull ToLongFunction countFunction, final @NotNull ToDoubleFunction totalTimeFunction, final @NotNull TimeUnit totalTimeFunctionUnit) { - return new CumulativeFunctionTimer<>( - id, obj, countFunction, totalTimeFunction, totalTimeFunctionUnit, getBaseTimeUnit()); + return new SentryFunctionTimer<>( + id, + obj, + countFunction, + totalTimeFunction, + totalTimeFunctionUnit, + getBaseTimeUnit(), + this, + createMetricInfo(id, ".count", null), + createMetricInfo(id, ".total_time", MetricsUnit.Duration.MILLISECOND)); } @Override @@ -238,6 +245,8 @@ private void publishPassiveMeter(final @NotNull Meter meter) { publishLongTaskTimer((LongTaskTimer) meter); } else if (meter instanceof SentryFunctionCounter) { ((SentryFunctionCounter) meter).poll(); + } else if (meter instanceof SentryFunctionTimer) { + ((SentryFunctionTimer) meter).poll(); } } @@ -269,6 +278,8 @@ private void publishLongTaskTimer(final @NotNull LongTaskTimer timer) { private void onMeterRemoved(final @NotNull Meter meter) { if (meter instanceof SentryFunctionCounter) { ((SentryFunctionCounter) meter).markRemoved(); + } else if (meter instanceof SentryFunctionTimer) { + ((SentryFunctionTimer) meter).markRemoved(); } } diff --git a/sentry-micrometer/src/test/kotlin/io/sentry/micrometer/SentryFunctionTimerTest.kt b/sentry-micrometer/src/test/kotlin/io/sentry/micrometer/SentryFunctionTimerTest.kt new file mode 100644 index 0000000000..d0241f7546 --- /dev/null +++ b/sentry-micrometer/src/test/kotlin/io/sentry/micrometer/SentryFunctionTimerTest.kt @@ -0,0 +1,282 @@ +package io.sentry.micrometer + +import com.google.common.truth.Truth.assertThat +import io.micrometer.core.instrument.Clock +import io.micrometer.core.instrument.FunctionTimer +import io.sentry.IScopes +import io.sentry.Sentry +import io.sentry.SentryOptions +import io.sentry.metrics.IMetricsApi +import io.sentry.metrics.MetricsUnit +import io.sentry.test.initForTest +import java.util.concurrent.ScheduledExecutorService +import java.util.concurrent.ScheduledFuture +import java.util.concurrent.TimeUnit +import java.util.concurrent.atomic.AtomicInteger +import kotlin.test.AfterTest +import kotlin.test.BeforeTest +import kotlin.test.Test +import org.mockito.kotlin.any +import org.mockito.kotlin.anyOrNull +import org.mockito.kotlin.argumentCaptor +import org.mockito.kotlin.eq +import org.mockito.kotlin.mock +import org.mockito.kotlin.never +import org.mockito.kotlin.times +import org.mockito.kotlin.verify +import org.mockito.kotlin.verifyNoInteractions +import org.mockito.kotlin.whenever + +class SentryFunctionTimerTest { + private val registries = mutableListOf() + + @BeforeTest + fun setUp() { + initForTest { it.dsn = "https://key@sentry.io/proj" } + } + + @AfterTest + fun tearDown() { + registries.forEach(SentryMeterRegistry::close) + Sentry.close() + } + + @Test + fun `callbacks are not invoked during registration`() { + val registry = pollingRegistry() + val state = State(10, 2500.0) + val countInvocations = AtomicInteger() + val totalTimeInvocations = AtomicInteger() + + FunctionTimer.builder( + "requests", + state, + { + countInvocations.incrementAndGet() + it.count + }, + { + totalTimeInvocations.incrementAndGet() + it.totalTime + }, + TimeUnit.MILLISECONDS, + ) + .register(registry) + + assertThat(countInvocations.get()).isEqualTo(0) + assertThat(totalTimeInvocations.get()).isEqualTo(0) + registry.pollMeters() + assertThat(countInvocations.get()).isEqualTo(1) + assertThat(totalTimeInvocations.get()).isEqualTo(1) + } + + @Test + fun `establishes baselines then emits count and millisecond deltas`() { + val metrics = installMetricsApi() + val registry = pollingRegistry() + val state = State(10, 2.5) + registerTimer(registry, "request.duration", state, TimeUnit.SECONDS) + + registry.pollMeters() + registry.pollMeters() + verifyNoInteractions(metrics) + + state.count = 13 + state.totalTime = 4.0 + registry.pollMeters() + + verify(metrics).count(eq("request_duration.count"), eq(3.0), anyOrNull(), any()) + verify(metrics) + .count( + eq("request_duration.total_time"), + eq(1500.0), + eq(MetricsUnit.Duration.MILLISECOND), + any(), + ) + verify(metrics, never()).gauge(any(), anyOrNull(), anyOrNull(), any()) + verify(metrics, never()).distribution(any(), anyOrNull(), anyOrNull(), any()) + } + + @Test + fun `count and total time reset independently`() { + val metrics = installMetricsApi() + val registry = pollingRegistry() + val state = State(10, 1000.0) + registerTimer(registry, "requests", state) + registry.pollMeters() + + state.count = 7 + state.totalTime = 1300.0 + registry.pollMeters() + state.count = 9 + state.totalTime = 200.0 + registry.pollMeters() + state.totalTime = 250.0 + registry.pollMeters() + + verify(metrics).count(eq("requests.count"), eq(2.0), anyOrNull(), any()) + verify(metrics) + .count( + eq("requests.total_time"), + eq(300.0), + eq(MetricsUnit.Duration.MILLISECOND), + any(), + ) + verify(metrics) + .count( + eq("requests.total_time"), + eq(50.0), + eq(MetricsUnit.Duration.MILLISECOND), + any(), + ) + verify(metrics, times(3)).count(any(), anyOrNull(), anyOrNull(), any()) + } + + @Test + fun `count can advance while total time waits for its first finite baseline`() { + val metrics = installMetricsApi() + val registry = pollingRegistry() + val state = State(10, Double.NaN) + registerTimer(registry, "requests", state) + registry.pollMeters() + + state.count = 12 + state.totalTime = 100.0 + registry.pollMeters() + state.count = 15 + state.totalTime = 150.0 + registry.pollMeters() + + verify(metrics).count(eq("requests.count"), eq(2.0), anyOrNull(), any()) + verify(metrics).count(eq("requests.count"), eq(3.0), anyOrNull(), any()) + verify(metrics) + .count( + eq("requests.total_time"), + eq(50.0), + eq(MetricsUnit.Duration.MILLISECOND), + any(), + ) + verify(metrics, times(3)).count(any(), anyOrNull(), anyOrNull(), any()) + } + + @Test + fun `non-finite total time leaves its baseline unchanged`() { + val metrics = installMetricsApi() + val registry = pollingRegistry() + val state = State(10, 100.0) + registerTimer(registry, "requests", state) + registry.pollMeters() + + state.count = 12 + state.totalTime = Double.NaN + registry.pollMeters() + state.totalTime = 150.0 + registry.pollMeters() + + verify(metrics).count(eq("requests.count"), eq(2.0), anyOrNull(), any()) + verify(metrics) + .count( + eq("requests.total_time"), + eq(50.0), + eq(MetricsUnit.Duration.MILLISECOND), + any(), + ) + verify(metrics, times(2)).count(any(), anyOrNull(), anyOrNull(), any()) + } + + @Test + fun `removing and re-registering clears both baselines`() { + val metrics = installMetricsApi() + val registry = pollingRegistry() + val firstState = State(10, 100.0) + val first = registerTimer(registry, "requests", firstState) + registry.pollMeters() + firstState.count = 12 + firstState.totalTime = 150.0 + registry.pollMeters() + registry.remove(first) + + val secondState = State(100, 1000.0) + registerTimer(registry, "requests", secondState) + registry.pollMeters() + secondState.count = 105 + secondState.totalTime = 1200.0 + registry.pollMeters() + + verify(metrics).count(eq("requests.count"), eq(2.0), anyOrNull(), any()) + verify(metrics).count(eq("requests.count"), eq(5.0), anyOrNull(), any()) + verify(metrics) + .count( + eq("requests.total_time"), + eq(50.0), + eq(MetricsUnit.Duration.MILLISECOND), + any(), + ) + verify(metrics) + .count( + eq("requests.total_time"), + eq(200.0), + eq(MetricsUnit.Duration.MILLISECOND), + any(), + ) + verify(metrics, times(4)).count(any(), anyOrNull(), anyOrNull(), any()) + } + + @Test + fun `count and total time produce a weighted mean across instances`() { + val metrics = installMetricsApi() + val registry = pollingRegistry() + val firstState = State(10, 1000.0) + val secondState = State(20, 2000.0) + registerTimer(registry, "requests", firstState, tagValue = "first") + registerTimer(registry, "requests", secondState, tagValue = "second") + registry.pollMeters() + + firstState.count += 2 + firstState.totalTime += 300.0 + secondState.count += 3 + secondState.totalTime += 900.0 + registry.pollMeters() + + val names = argumentCaptor() + val values = argumentCaptor() + verify(metrics, times(4)).count(names.capture(), values.capture(), anyOrNull(), any()) + val emitted = names.allValues.zip(values.allValues) + val totalCount = emitted.filter { it.first == "requests.count" }.sumOf { it.second } + val totalTime = emitted.filter { it.first == "requests.total_time" }.sumOf { it.second } + + assertThat(totalTime / totalCount).isEqualTo(240.0) + } + + private fun registerTimer( + registry: SentryMeterRegistry, + name: String, + state: State, + unit: TimeUnit = TimeUnit.MILLISECONDS, + tagValue: String? = null, + ): FunctionTimer { + val builder = FunctionTimer.builder(name, state, { it.count }, { it.totalTime }, unit) + if (tagValue != null) { + builder.tag("instance", tagValue) + } + return builder.register(registry) + } + + private fun pollingRegistry(): SentryMeterRegistry { + val scheduler = mock() + val task = mock>() + whenever(scheduler.scheduleAtFixedRate(any(), any(), any(), any())).thenReturn(task) + return SentryMeterRegistry(60_000, Clock.SYSTEM, scheduler).also(registries::add) + } + + private fun installMetricsApi(): IMetricsApi { + val metrics = mock() + val scopes = mock() + whenever(scopes.metrics()).thenReturn(metrics) + whenever(scopes.options).thenReturn(SentryOptions()) + Sentry.setCurrentScopes(scopes) + return metrics + } + + private data class State(var count: Long, var totalTime: Double) +}