Skip to content

Commit e907d8d

Browse files
runningcodeclaude
runningcode
and
claude
authored
ref(checkin): Measure check-in durations with Stopwatch (JAVA-576) (#6032)
* ref(checkin): Measure check-in durations with Stopwatch (JAVA-576) All four check-in paths kept a `long startTime = System.nanoTime()` and subtracted it in a finally block: CheckInUtils and the SentryCheckInAdvice in sentry-spring, sentry-spring-jakarta and sentry-spring-7. They now share one Stopwatch, which takes its clock from the options. Inert on every path that ships. The options hand the check-in path a JavaMonotonicTicker, whose tickNanos() is System.nanoTime(), so the serialized duration is unchanged to the bit. A new test brackets a tick between two nanoTime readings, pinning the source rather than merely the resolution. SentryAndroidOptions does override the ticker with a boottime one, but nothing reaches it from here: check-ins have no Android integration -- no WorkManager, JobScheduler or AlarmManager wrapper, no manifest option, no Android docs. Measuring a check-in across device sleep is a change for the next major. An uninitialized SDK still reaches a clock: NoOpScopes.getOptions() hands back empty options, whose ticker is the JVM one. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> * test(checkin): Pin the check-in duration to the options ticker (JAVA-576) The duration was measured off System.nanoTime() directly, so a test could only assert it was some nonzero float. Now that the clock arrives through SentryOptions.getMonotonicTicker(), a test can hand the check-in path a ticker it controls and assert an exact value. Two paths are worth pinning: the callable returning normally, where only the terminal check-in carries a duration and the IN_PROGRESS one does not, and the callable throwing, where the finally block still has to report the time that passed. Both fail against the pre-refactor code. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> --------- Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
1 parent 744ff64 commit e907d8d

5 files changed

Lines changed: 101 additions & 8 deletions

File tree

‎sentry-spring-7/src/main/java/io/sentry/spring7/checkin/SentryCheckInAdvice.java‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
import io.sentry.ScopesAdapter;
1010
import io.sentry.SentryLevel;
1111
import io.sentry.protocol.SentryId;
12+
import io.sentry.time.Stopwatch;
1213
import io.sentry.util.Objects;
1314
import io.sentry.util.TracingUtils;
1415
import java.lang.reflect.Method;
@@ -91,7 +92,8 @@ public Object invoke(final @NotNull MethodInvocation invocation) throws Throwabl
9192
TracingUtils.startNewTrace(scopes);
9293

9394
@Nullable SentryId checkInId = null;
94-
final long startTime = System.nanoTime();
95+
final @NotNull Stopwatch stopwatch =
96+
Stopwatch.started(scopes.getOptions().getMonotonicTicker());
9597
boolean didError = false;
9698

9799
try {
@@ -105,7 +107,7 @@ public Object invoke(final @NotNull MethodInvocation invocation) throws Throwabl
105107
} finally {
106108
final @NotNull CheckInStatus status = didError ? CheckInStatus.ERROR : CheckInStatus.OK;
107109
CheckIn checkIn = new CheckIn(checkInId, monitorSlug, status);
108-
checkIn.setDuration(DateUtils.nanosToSeconds(System.nanoTime() - startTime));
110+
checkIn.setDuration(DateUtils.nanosToSeconds(stopwatch.elapsedNanos()));
109111
scopes.captureCheckIn(checkIn);
110112
}
111113
}

‎sentry-spring-jakarta/src/main/java/io/sentry/spring/jakarta/checkin/SentryCheckInAdvice.java‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
import io.sentry.ScopesAdapter;
1010
import io.sentry.SentryLevel;
1111
import io.sentry.protocol.SentryId;
12+
import io.sentry.time.Stopwatch;
1213
import io.sentry.util.Objects;
1314
import io.sentry.util.TracingUtils;
1415
import java.lang.reflect.Method;
@@ -91,7 +92,8 @@ public Object invoke(final @NotNull MethodInvocation invocation) throws Throwabl
9192
TracingUtils.startNewTrace(scopes);
9293

9394
@Nullable SentryId checkInId = null;
94-
final long startTime = System.nanoTime();
95+
final @NotNull Stopwatch stopwatch =
96+
Stopwatch.started(scopes.getOptions().getMonotonicTicker());
9597
boolean didError = false;
9698

9799
try {
@@ -105,7 +107,7 @@ public Object invoke(final @NotNull MethodInvocation invocation) throws Throwabl
105107
} finally {
106108
final @NotNull CheckInStatus status = didError ? CheckInStatus.ERROR : CheckInStatus.OK;
107109
CheckIn checkIn = new CheckIn(checkInId, monitorSlug, status);
108-
checkIn.setDuration(DateUtils.nanosToSeconds(System.nanoTime() - startTime));
110+
checkIn.setDuration(DateUtils.nanosToSeconds(stopwatch.elapsedNanos()));
109111
scopes.captureCheckIn(checkIn);
110112
}
111113
}

‎sentry-spring/src/main/java/io/sentry/spring/checkin/SentryCheckInAdvice.java‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
import io.sentry.ScopesAdapter;
1010
import io.sentry.SentryLevel;
1111
import io.sentry.protocol.SentryId;
12+
import io.sentry.time.Stopwatch;
1213
import io.sentry.util.Objects;
1314
import io.sentry.util.TracingUtils;
1415
import java.lang.reflect.Method;
@@ -94,7 +95,8 @@ public Object invoke(final @NotNull MethodInvocation invocation) throws Throwabl
9495
TracingUtils.startNewTrace(scopes);
9596

9697
@Nullable SentryId checkInId = null;
97-
final long startTime = System.nanoTime();
98+
final @NotNull Stopwatch stopwatch =
99+
Stopwatch.started(scopes.getOptions().getMonotonicTicker());
98100
boolean didError = false;
99101

100102
try {
@@ -108,7 +110,7 @@ public Object invoke(final @NotNull MethodInvocation invocation) throws Throwabl
108110
} finally {
109111
final @NotNull CheckInStatus status = didError ? CheckInStatus.ERROR : CheckInStatus.OK;
110112
CheckIn checkIn = new CheckIn(checkInId, monitorSlug, status);
111-
checkIn.setDuration(DateUtils.nanosToSeconds(System.nanoTime() - startTime));
113+
checkIn.setDuration(DateUtils.nanosToSeconds(stopwatch.elapsedNanos()));
112114
scopes.captureCheckIn(checkIn);
113115
}
114116
}

‎sentry/src/main/java/io/sentry/util/CheckInUtils.java‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
import io.sentry.MonitorConfig;
1010
import io.sentry.Sentry;
1111
import io.sentry.protocol.SentryId;
12+
import io.sentry.time.Stopwatch;
1213
import java.util.List;
1314
import java.util.concurrent.Callable;
1415
import org.jetbrains.annotations.ApiStatus;
@@ -37,7 +38,8 @@ public static <U> U withCheckIn(
3738
try (final @NotNull ISentryLifecycleToken ignored =
3839
Sentry.forkedScopes("CheckInUtils").makeCurrent()) {
3940
final @NotNull IScopes scopes = Sentry.getCurrentScopes();
40-
final long startTime = System.nanoTime();
41+
final @NotNull Stopwatch stopwatch =
42+
Stopwatch.started(scopes.getOptions().getMonotonicTicker());
4143
boolean didError = false;
4244

4345
TracingUtils.startNewTrace(scopes);
@@ -61,7 +63,7 @@ public static <U> U withCheckIn(
6163
if (environment != null) {
6264
checkIn.setEnvironment(environment);
6365
}
64-
checkIn.setDuration(DateUtils.nanosToSeconds(System.nanoTime() - startTime));
66+
checkIn.setDuration(DateUtils.nanosToSeconds(stopwatch.elapsedNanos()));
6567
scopes.captureCheckIn(checkIn);
6668
}
6769
}

‎sentry/src/test/java/io/sentry/util/CheckInUtilsTest.kt‎

Lines changed: 85 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,7 @@
11
package io.sentry.util
22

3+
import com.google.common.truth.Truth.assertThat
4+
import io.sentry.CheckIn
35
import io.sentry.CheckInStatus
46
import io.sentry.FilterString
57
import io.sentry.IScopes
@@ -9,18 +11,26 @@ import io.sentry.MonitorSchedule
911
import io.sentry.MonitorScheduleUnit
1012
import io.sentry.Sentry
1113
import io.sentry.SentryOptions
14+
import io.sentry.time.MonotonicTicker
15+
import io.sentry.time.TestMonotonicTicker
1216
import java.lang.AssertionError
1317
import java.lang.RuntimeException
18+
import java.util.concurrent.TimeUnit.MILLISECONDS
19+
import java.util.concurrent.TimeUnit.SECONDS
1420
import kotlin.test.Test
1521
import kotlin.test.assertEquals
22+
import kotlin.test.assertFailsWith
1623
import kotlin.test.assertFalse
1724
import kotlin.test.assertSame
1825
import kotlin.test.assertTrue
1926
import org.mockito.Mockito
2027
import org.mockito.kotlin.any
28+
import org.mockito.kotlin.argumentCaptor
2129
import org.mockito.kotlin.check
2230
import org.mockito.kotlin.inOrder
2331
import org.mockito.kotlin.mock
32+
import org.mockito.kotlin.times
33+
import org.mockito.kotlin.verify
2434
import org.mockito.kotlin.whenever
2535

2636
class CheckInUtilsTest {
@@ -143,6 +153,7 @@ class CheckInUtilsTest {
143153
sentry.`when`<Any> { Sentry.forkedScopes(any()) }.then { scopes.forkedScopes("test") }
144154
whenever(scopes.forkedScopes(any())).thenReturn(scopes)
145155
whenever(scopes.makeCurrent()).thenReturn(lifecycleToken)
156+
whenever(scopes.options).thenReturn(SentryOptions())
146157

147158
try {
148159
CheckInUtils.withCheckIn("monitor-1") { throw RuntimeException("thrown on purpose") }
@@ -312,4 +323,78 @@ class CheckInUtilsTest {
312323
assertEquals("America/Los_Angeles", monitorConfig.timezone)
313324
}
314325
}
326+
327+
@Test
328+
fun `resolves a ticker that ticks on System nanoTime`() {
329+
// The clock the check-in path reads. Bracketing a tick between two System.nanoTime() readings
330+
// pins the source, not just the resolution: a ticker on any other monotonic source reports a
331+
// different epoch and would fall outside the bracket.
332+
val ticker = SentryOptions().monotonicTicker
333+
334+
val before = System.nanoTime()
335+
val tick = ticker.tickNanos()
336+
val after = System.nanoTime()
337+
338+
assertThat(tick).isAtLeast(before)
339+
assertThat(tick).isAtMost(after)
340+
}
341+
342+
@Test
343+
fun `reports the duration the ticker advanced by`() {
344+
val ticker = TestMonotonicTicker()
345+
346+
val checkIns =
347+
captureCheckIns(ticker) {
348+
CheckInUtils.withCheckIn("monitor-1") { ticker.advance(1500, MILLISECONDS) }
349+
}
350+
351+
assertThat(checkIns.map { it.status })
352+
.containsExactly(CheckInStatus.IN_PROGRESS.apiName(), CheckInStatus.OK.apiName())
353+
.inOrder()
354+
assertThat(checkIns.first().duration).isNull()
355+
assertThat(checkIns.last().duration).isEqualTo(1.5)
356+
}
357+
358+
@Test
359+
fun `reports the duration when the callable throws`() {
360+
val ticker = TestMonotonicTicker()
361+
362+
val checkIns =
363+
captureCheckIns(ticker) {
364+
assertFailsWith<RuntimeException> {
365+
CheckInUtils.withCheckIn("monitor-1") {
366+
ticker.advance(2, SECONDS)
367+
throw RuntimeException("thrown on purpose")
368+
}
369+
}
370+
}
371+
372+
assertThat(checkIns.last().status).isEqualTo(CheckInStatus.ERROR.apiName())
373+
assertThat(checkIns.last().duration).isEqualTo(2.0)
374+
}
375+
376+
/**
377+
* Runs [block] against scopes whose options tick on [ticker], and returns every check-in it
378+
* captured, in order.
379+
*/
380+
private fun captureCheckIns(ticker: MonotonicTicker, block: () -> Unit): List<CheckIn> {
381+
Mockito.mockStatic(Sentry::class.java).use { sentry ->
382+
val scopes = mock<IScopes>()
383+
val options =
384+
object : SentryOptions() {
385+
override fun getMonotonicTicker(): MonotonicTicker = ticker
386+
}
387+
sentry.`when`<Any> { Sentry.getCurrentScopes() }.thenReturn(scopes)
388+
sentry.`when`<Any> { Sentry.forkedScopes(any()) }.then { scopes.forkedScopes("test") }
389+
whenever(scopes.forkedScopes(any())).thenReturn(scopes)
390+
whenever(scopes.makeCurrent()).thenReturn(mock<ISentryLifecycleToken>())
391+
whenever(scopes.options).thenReturn(options)
392+
393+
block()
394+
395+
val captor = argumentCaptor<CheckIn>()
396+
verify(scopes, times(2)).captureCheckIn(captor.capture())
397+
return captor.allValues
398+
}
399+
}
315400
}

0 commit comments

Comments
 (0)