From 95c2a5b2d94fd38748a0536ed3cdf1e64ffa6d50 Mon Sep 17 00:00:00 2001 From: Nelson Osacky Date: Thu, 12 Nov 2026 14:57:52 +0100 Subject: [PATCH 1/5] fix(core): End transactions at the deadline after the device sleeps (JAVA-642) The deadline timer counts on System.nanoTime(), which stops while an Android device is suspended. It ran hours late, and after a process freeze it raced the main thread, so ui.load transactions ended hours after the deadline, or measured TTID, TTFD and the app start to a late frame and finished as ok. SentryTracer now measures the deadline on the monotonic ticker, which counts suspend, and ends the transaction and its open spans at the wall time the deadline was reached. Once it has passed, every way of finishing the transaction takes that outcome. ActivityLifecycleIntegration applies it before handling a late first frame, full display or destroy, and PerformanceAndroidEventProcessor adds no app start measurement when the app start span was cut short. Co-Authored-By: Claude Opus 5.5 --- .../core/ActivityLifecycleIntegration.java | 57 +++++- .../PerformanceAndroidEventProcessor.java | 21 ++- .../core/ActivityLifecycleIntegrationTest.kt | 146 ++++++++++++++- .../PerformanceAndroidEventProcessorTest.kt | 24 ++- sentry/api/sentry.api | 1 + .../src/main/java/io/sentry/SentryTracer.java | 126 +++++++++++-- .../test/java/io/sentry/SentryTracerTest.kt | 175 +++++++++++++++++- 7 files changed, 525 insertions(+), 25 deletions(-) diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java b/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java index 0c3b7d8d5ff..4c318538b63 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java @@ -25,6 +25,7 @@ import io.sentry.SentryLevel; import io.sentry.SentryNanotimeDate; import io.sentry.SentryOptions; +import io.sentry.SentryTracer; import io.sentry.SpanOptions; import io.sentry.SpanStatus; import io.sentry.TracesSamplingDecision; @@ -522,6 +523,7 @@ private void finishTransaction( final @Nullable ISpan ttidSpan, final @Nullable ISpan ttfdSpan) { if (transaction != null) { + finishTransactionIfDeadlinePassed(transaction, ttidSpan, ttfdSpan); // if io.sentry.traces.activity.auto-finish.enable is disabled, transaction may be already // finished manually when this method is called. if (transaction.isFinished()) { @@ -581,6 +583,7 @@ public void onActivityCreated( scopes.configureScope(scope -> scope.setScreen(activityClassName)); } startTracing(activity); + final @Nullable ITransaction transaction = activitiesWithOngoingTransactions.get(activity); final @Nullable ISpan ttidSpan = ttidSpanMap.get(activity); final @Nullable ISpan ttfdSpan = ttfdSpanMap.get(activity); @@ -591,7 +594,7 @@ public void onActivityCreated( && ttfdSpan != null && fullyDisplayedReporter != null) { fullyDisplayedReporter.registerFullyDrawnListener( - () -> onFullFrameDrawn(ttidSpan, ttfdSpan)); + () -> onFullFrameDrawn(transaction, ttidSpan, ttfdSpan)); } } } @@ -654,15 +657,19 @@ public void onActivityResumed(final @NotNull Activity activity) { } if (performanceEnabled) { + final @Nullable ITransaction transaction = activitiesWithOngoingTransactions.get(activity); final @Nullable ISpan ttidSpan = ttidSpanMap.get(activity); final @Nullable ISpan ttfdSpan = ttfdSpanMap.get(activity); if (activity.getWindow() != null) { FirstDrawDoneListener.registerForNextDraw( - activity, () -> onFirstFrameDrawn(ttfdSpan, ttidSpan), buildInfoProvider); + activity, + () -> onFirstFrameDrawn(transaction, ttfdSpan, ttidSpan), + buildInfoProvider); } else { // Posting a task to the main thread's handler will make it executed after it finished // its current job. That is, right after the activity draws the layout. - new Handler(Looper.getMainLooper()).post(() -> onFirstFrameDrawn(ttfdSpan, ttidSpan)); + new Handler(Looper.getMainLooper()) + .post(() -> onFirstFrameDrawn(transaction, ttfdSpan, ttidSpan)); } } } @@ -715,6 +722,10 @@ public void onActivityDestroyed(final @NotNull Activity activity) { helper.clear(); } if (performanceEnabled) { + final ISpan ttidSpan = ttidSpanMap.get(activity); + final ISpan ttfdSpan = ttfdSpanMap.get(activity); + finishTransactionIfDeadlinePassed( + activitiesWithOngoingTransactions.get(activity), ttidSpan, ttfdSpan); // in case the appStartSpan isn't completed yet, we finish it as cancelled to avoid // memory leak @@ -724,8 +735,6 @@ public void onActivityDestroyed(final @NotNull Activity activity) { } // we finish the ttidSpan as cancelled in case it isn't completed yet - final ISpan ttidSpan = ttidSpanMap.get(activity); - final ISpan ttfdSpan = ttfdSpanMap.get(activity); finishSpan(ttidSpan, SpanStatus.DEADLINE_EXCEEDED); // we finish the ttfdSpan as deadline_exceeded in case it isn't completed yet @@ -796,7 +805,12 @@ private void cancelTtfdAutoClose() { } } - private void onFirstFrameDrawn(final @Nullable ISpan ttfdSpan, final @Nullable ISpan ttidSpan) { + private void onFirstFrameDrawn( + final @Nullable ITransaction transaction, + final @Nullable ISpan ttfdSpan, + final @Nullable ISpan ttidSpan) { + finishTransactionIfDeadlinePassed(transaction, ttidSpan, ttfdSpan); + // app start span final @NotNull AppStartMetrics appStartMetrics = AppStartMetrics.getInstance(); final @NotNull TimeSpan appStartTimeSpan = appStartMetrics.getAppStartTimeSpan(); @@ -853,7 +867,11 @@ private void stopTimeSpanAtDate( } } - private void onFullFrameDrawn(final @NotNull ISpan ttidSpan, final @NotNull ISpan ttfdSpan) { + private void onFullFrameDrawn( + final @Nullable ITransaction transaction, + final @NotNull ISpan ttidSpan, + final @NotNull ISpan ttfdSpan) { + finishTransactionIfDeadlinePassed(transaction, ttidSpan, ttfdSpan); cancelTtfdAutoClose(); // Sentry.reportFullyDisplayed can be run in any thread, so we have to ensure synchronization // with first frame drawn @@ -878,6 +896,31 @@ private void onFullFrameDrawn(final @NotNull ISpan ttidSpan, final @NotNull ISpa } } + /** + * Ends the transaction at its deadline if that has passed, because the device slept or the + * process was frozen before the deadline timer could run. + * + *

On a device that stayed awake the deadline timer would have ended the transaction and its + * spans before the activity callback that calls this. Ending them here first lets the callback + * carry on as it would have there: its spans are finished, so it measures nothing. + */ + private void finishTransactionIfDeadlinePassed( + final @Nullable ITransaction transaction, + final @Nullable ISpan ttidSpan, + final @Nullable ISpan ttfdSpan) { + if (!(transaction instanceof SentryTracer) + || !((SentryTracer) transaction).hasDeadlinePassed()) { + return; + } + // When the TTFD auto-close is due before the deadline, on that device it had already ended the + // TTFD span. + if (options != null && TTFD_TIMEOUT_MILLIS < options.getDeadlineTimeout()) { + finishExceededTtfdSpan(ttfdSpan, ttidSpan); + } + // Past the deadline, finishing ends the transaction at the deadline, with its status. + transaction.finish(); + } + private void finishExceededTtfdSpan( final @Nullable ISpan ttfdSpan, final @Nullable ISpan ttidSpan) { if (ttfdSpan == null || ttfdSpan.isFinished()) { diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/PerformanceAndroidEventProcessor.java b/sentry-android-core/src/main/java/io/sentry/android/core/PerformanceAndroidEventProcessor.java index 503bd1d856b..37e1a0a0396 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/PerformanceAndroidEventProcessor.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/PerformanceAndroidEventProcessor.java @@ -100,7 +100,8 @@ public SentryEvent process(@NotNull SentryEvent event, @NotNull Hint hint) { && isStandaloneAppStartTxn && !traceContext.getData().containsKey(APP_START_SCREEN_DATA); - if (appStartMetrics.shouldSendStartMeasurements(isHeadlessStandaloneAppStartTxn)) { + if (appStartMetrics.shouldSendStartMeasurements(isHeadlessStandaloneAppStartTxn) + && !isAppStartSpanCutShort(transaction)) { final @NotNull TimeSpan appStartTimeSpan = isHeadlessStandaloneAppStartTxn ? appStartMetrics.getAppStartTimeSpanForHeadless() @@ -291,6 +292,24 @@ private boolean hasAppStartSpan(final @NotNull SentryTransaction txn) { return context != null && context.getOperation().equals(STANDALONE_APP_START_OP); } + /** + * Whether something ended the app.start span before the first frame did, such as the deadline or + * the activity being destroyed. + * + *

On a device that stays awake the app start time span is still running then, so nothing is + * measured. After the device slept or the process was frozen, a first frame drawn since may + * already have stopped it, hours after the app.start span ended. + */ + private static boolean isAppStartSpanCutShort(final @NotNull SentryTransaction txn) { + for (final @NotNull SentrySpan span : txn.getSpans()) { + if (span.getOp().contentEquals(APP_START_COLD) + || span.getOp().contentEquals(APP_START_WARM)) { + return span.getStatus() != SpanStatus.OK; + } + } + return false; + } + private void attachAppStartSpans( final @NotNull AppStartMetrics appStartMetrics, final @NotNull AppStartMetrics.AppStartType appStartType, diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt index 1a88c1bec6d..27c2783cc96 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt +++ b/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt @@ -15,6 +15,7 @@ import android.view.View import android.view.ViewTreeObserver import androidx.test.core.app.ApplicationProvider import androidx.test.ext.junit.runners.AndroidJUnit4 +import com.google.common.truth.Truth.assertThat import io.sentry.DateUtils import io.sentry.FullyDisplayedReporter import io.sentry.IScope @@ -44,6 +45,7 @@ import io.sentry.protocol.SentryId import io.sentry.protocol.TransactionNameSource import io.sentry.test.DeferredExecutorService import io.sentry.test.getProperty +import io.sentry.time.TestMonotonicTicker import java.util.concurrent.Future import java.util.concurrent.TimeUnit import kotlin.test.AfterTest @@ -68,6 +70,7 @@ import org.mockito.kotlin.clearInvocations import org.mockito.kotlin.eq import org.mockito.kotlin.mock import org.mockito.kotlin.never +import org.mockito.kotlin.spy import org.mockito.kotlin.times import org.mockito.kotlin.verify import org.mockito.kotlin.whenever @@ -82,7 +85,12 @@ class ActivityLifecycleIntegrationTest { private class Fixture { val application = mock() val scopes = mock() - val options = SentryAndroidOptions().apply { dsn = "https://key@sentry.io/proj" } + val ticker = TestMonotonicTicker() + // SentryAndroidOptions is final and has no ticker setter, so a spy supplies the ticker. + val options = + spy(SentryAndroidOptions().apply { dsn = "https://key@sentry.io/proj" }).also { + whenever(it.monotonicTicker).thenReturn(ticker) + } val bundle = mock() val activityFramesTracker = mock() val transactionFinishedCallback = mock() @@ -2558,6 +2566,138 @@ class ActivityLifecycleIntegrationTest { assertNotEquals(0, lastUptimeMillis.nanoTimestamp()) } + @Test + fun `first frame drawn after the deadline passed ends the transaction at the deadline without TTID`() { + val sut = fixture.getSut { it.tracesSampleRate = 1.0 } + var nowMillis = START_MILLIS + fixture.options.dateProvider = SentryDateProvider { SentryNanotimeDate(nowMillis, 0) } + setAppStartTime(SentryNanotimeDate(START_MILLIS, 0)) + sut.register(fixture.scopes, fixture.options) + val view = fixture.createView() + val activity = createAndResumeActivity(sut, view) + val ttidSpan = sut.ttidSpanMap[activity]!! + val appStartSpan = sut.appStartSpan!! + + // the device sleeps before the first frame, and the deadline timer hasn't run yet + fixture.ticker.advance(3, TimeUnit.HOURS) + nowMillis += TimeUnit.HOURS.toMillis(3) + runFirstDraw(view) + + for (span in listOf(fixture.transaction, ttidSpan, appStartSpan)) { + assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(deadlineNanos()) + } + assertThat((ttidSpan as Span).measurements).isEmpty() + verify(fixture.scopes) + .captureTransaction( + check { + assertThat(it.measurements) + .doesNotContainKey(MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY) + }, + anyOrNull(), + anyOrNull(), + anyOrNull(), + ) + } + + @Test + fun `first frame drawn before the deadline still measures TTID`() { + val sut = fixture.getSut { it.tracesSampleRate = 1.0 } + var nowMillis = START_MILLIS + fixture.options.dateProvider = SentryDateProvider { SentryNanotimeDate(nowMillis, 0) } + setAppStartTime(SentryNanotimeDate(START_MILLIS, 0)) + sut.register(fixture.scopes, fixture.options) + val view = fixture.createView() + val activity = createAndResumeActivity(sut, view) + val ttidSpan = sut.ttidSpanMap[activity]!! + + fixture.ticker.advance(29, TimeUnit.SECONDS) + nowMillis += TimeUnit.SECONDS.toMillis(29) + runFirstDraw(view) + + assertThat(ttidSpan.status).isEqualTo(SpanStatus.OK) + assertThat(ttidSpan.finishDate!!.nanoTimestamp()) + .isEqualTo(TimeUnit.MILLISECONDS.toNanos(nowMillis)) + assertThat( + (ttidSpan as Span).measurements[MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY]!!.value + ) + .isEqualTo(TimeUnit.SECONDS.toMillis(29)) + assertThat(fixture.transaction.isFinished).isFalse() + } + + @Test + fun `full display reported after the deadline passed ends the TTFD span as its auto-close would, without TTFD`() { + val sut = fixture.getSut { + it.tracesSampleRate = 1.0 + it.isEnableTimeToFullDisplayTracing = true + } + var nowMillis = START_MILLIS + fixture.options.dateProvider = SentryDateProvider { SentryNanotimeDate(nowMillis, 0) } + setAppStartTime(SentryNanotimeDate(START_MILLIS, 0)) + sut.register(fixture.scopes, fixture.options) + val view = fixture.createView() + val activity = createAndResumeActivity(sut, view) + val ttidSpan = sut.ttidSpanMap[activity]!! + val ttfdSpan = sut.ttfdSpanMap[activity]!! + nowMillis += 1_000 + runFirstDraw(view) + + // the device sleeps before the app reports full display, and the timers haven't run yet + fixture.ticker.advance(3, TimeUnit.HOURS) + nowMillis += TimeUnit.HOURS.toMillis(3) + fixture.options.fullyDisplayedReporter.reportFullyDrawn() + + assertThat(ttfdSpan.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(ttfdSpan.finishDate).isEqualTo(ttidSpan.finishDate) + assertThat(ttfdSpan.description).endsWith(" - Deadline Exceeded") + assertThat((ttfdSpan as Span).measurements).isEmpty() + assertThat(fixture.transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + verify(fixture.scopes) + .captureTransaction( + check { + assertThat(it.measurements).doesNotContainKey(MeasurementValue.KEY_TIME_TO_FULL_DISPLAY) + }, + anyOrNull(), + anyOrNull(), + anyOrNull(), + ) + } + + @Test + fun `activity destroyed after the deadline passed ends the transaction at the deadline`() { + val sut = fixture.getSut { it.tracesSampleRate = 1.0 } + var nowMillis = START_MILLIS + fixture.options.dateProvider = SentryDateProvider { SentryNanotimeDate(nowMillis, 0) } + setAppStartTime(SentryNanotimeDate(START_MILLIS, 0)) + sut.register(fixture.scopes, fixture.options) + val activity = createAndResumeActivity(sut, fixture.createView()) + val ttidSpan = sut.ttidSpanMap[activity]!! + val appStartSpan = sut.appStartSpan!! + + fixture.ticker.advance(3, TimeUnit.HOURS) + nowMillis += TimeUnit.HOURS.toMillis(3) + sut.onActivityDestroyed(activity) + + for (span in listOf(fixture.transaction, ttidSpan, appStartSpan)) { + assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(deadlineNanos()) + } + } + + private fun createAndResumeActivity(sut: ActivityLifecycleIntegration, view: View): Activity { + val activity = mock() + whenever(activity.findViewById(any())).thenReturn(view) + sut.onActivityCreated(activity, fixture.bundle) + sut.onActivityResumed(activity) + return activity + } + + /** Where the deadline ends a ui.load that started at [START_MILLIS]. */ + private fun deadlineNanos(): Long = + TimeUnit.MILLISECONDS.toNanos( + START_MILLIS + TransactionOptions.DEFAULT_DEADLINE_TIMEOUT_AUTO_TRANSACTION + ) + private fun SentryTracer.isFinishing() = getProperty("finishStatus").getProperty("isFinishing") @@ -2645,6 +2785,10 @@ class ActivityLifecycleIntegrationTest { AppStartMetrics.getInstance().onActivityCreated(mock(), mock()) } } + + private companion object { + const val START_MILLIS = 1_000_000L + } } private open class SecondAppStartActivity : Activity() diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/PerformanceAndroidEventProcessorTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/PerformanceAndroidEventProcessorTest.kt index 0ab922fc32a..fa433e0b6f4 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/PerformanceAndroidEventProcessorTest.kt +++ b/sentry-android-core/src/test/java/io/sentry/android/core/PerformanceAndroidEventProcessorTest.kt @@ -67,7 +67,11 @@ class PerformanceAndroidEventProcessorTest { private val fixture = Fixture() - private fun createAppStartSpan(traceId: SentryId, coldStart: Boolean = true) = + private fun createAppStartSpan( + traceId: SentryId, + coldStart: Boolean = true, + status: SpanStatus = SpanStatus.OK, + ) = SentrySpan( 0.0, 1.0, @@ -76,7 +80,7 @@ class PerformanceAndroidEventProcessorTest { null, if (coldStart) APP_START_COLD else APP_START_WARM, "App Start", - SpanStatus.OK, + status, null, emptyMap(), emptyMap(), @@ -457,6 +461,22 @@ class PerformanceAndroidEventProcessorTest { assertFalse(tr.measurements.containsKey(MeasurementValue.KEY_APP_START_WARM)) } + @Test + fun `app start that the deadline ended before the first frame adds no measurement`() { + val sut = fixture.getSut() + var tr = createUiLoadTransaction() + tr.spans.add( + createAppStartSpan(tr.contexts.trace!!.traceId, status = SpanStatus.DEADLINE_EXCEEDED) + ) + // a first frame drawn after the device slept stopped the app start time span + setAppStart(fixture.options) + + tr = sut.process(tr, Hint()) + + assertThat(tr.measurements).doesNotContainKey(MeasurementValue.KEY_APP_START_COLD) + assertThat(tr.spans.map { it.op }).containsExactly(APP_START_COLD) + } + @Test fun `add cold start measurement for performance-v2`() { val sut = fixture.getSut(enablePerformanceV2 = true) diff --git a/sentry/api/sentry.api b/sentry/api/sentry.api index dfce80a93d8..2b7e530a8cc 100644 --- a/sentry/api/sentry.api +++ b/sentry/api/sentry.api @@ -4377,6 +4377,7 @@ public final class io/sentry/SentryTracer : io/sentry/ITransaction { public fun getTag (Ljava/lang/String;)Ljava/lang/String; public fun getThrowable ()Ljava/lang/Throwable; public fun getTransactionNameSource ()Lio/sentry/protocol/TransactionNameSource; + public fun hasDeadlinePassed ()Z public fun isFinished ()Z public fun isNoOp ()Z public fun isProfileSampled ()Ljava/lang/Boolean; diff --git a/sentry/src/main/java/io/sentry/SentryTracer.java b/sentry/src/main/java/io/sentry/SentryTracer.java index cc1ce8e22ac..55f513bc0d9 100644 --- a/sentry/src/main/java/io/sentry/SentryTracer.java +++ b/sentry/src/main/java/io/sentry/SentryTracer.java @@ -5,6 +5,7 @@ import io.sentry.protocol.SentryId; import io.sentry.protocol.SentryTransaction; import io.sentry.protocol.TransactionNameSource; +import io.sentry.time.Deadline; import io.sentry.util.AutoClosableReentrantLock; import io.sentry.util.CollectionUtils; import io.sentry.util.Objects; @@ -15,6 +16,7 @@ import java.util.Map; import java.util.concurrent.CopyOnWriteArrayList; import java.util.concurrent.Future; +import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicBoolean; import java.util.concurrent.atomic.AtomicReference; import org.jetbrains.annotations.ApiStatus; @@ -49,6 +51,24 @@ public final class SentryTracer implements ITransaction { private final @NotNull AtomicBoolean isIdleFinishTimerRunning = new AtomicBoolean(false); private final @NotNull AtomicBoolean isDeadlineTimerRunning = new AtomicBoolean(false); + /** + * When the deadline timeout is reached, or null without one. + * + *

The deadline timer counts on a clock that stops while an Android device is suspended, so it + * can run hours late. After the process was frozen it is overdue and races the app's own threads. + * This deadline keeps counting through both, so whichever path finishes the transaction can tell + * that the deadline has passed, and end it where the timer would have on a device that stayed + * awake. + */ + private final @Nullable Deadline deadline; + + /** The wall time at which {@link #deadline} passes, and where the deadline ends the spans. */ + private final @Nullable SentryDate deadlineTimestamp; + + // After a thaw the overdue deadline timer and the app's threads can finish the transaction at the + // same moment, and it must be captured only once. + private final @NotNull AtomicBoolean isRootFinishClaimed = new AtomicBoolean(false); + private @NotNull TransactionNameSource transactionNameSource; private final @NotNull Instrumenter instrumenter; private final @NotNull Contexts contexts = new Contexts(); @@ -99,6 +119,21 @@ public SentryTracer( this.compositePerformanceCollector.start(this); } + final @Nullable Long deadlineTimeout = transactionOptions.getDeadlineTimeout(); + if (deadlineTimeout != null) { + final @NotNull SentryOptions options = scopes.getOptions(); + this.deadline = + Deadline.after(options.getMonotonicTicker(), deadlineTimeout, TimeUnit.MILLISECONDS); + // Read from the date provider like every other span timestamp, so that they compare. + this.deadlineTimestamp = + new SentryLongDate( + options.getDateProvider().now().nanoTimestamp() + + TimeUnit.MILLISECONDS.toNanos(deadlineTimeout)); + } else { + this.deadline = null; + this.deadlineTimestamp = null; + } + if (transactionOptions.getIdleTimeout() != null || transactionOptions.getDeadlineTimeout() != null) { timersEnabled = true; @@ -144,23 +179,64 @@ private void onIdleTimeoutReached() { isIdleFinishTimerRunning.set(false); } - private void onDeadlineTimeoutReached() { - final @Nullable SpanStatus status = getStatus(); + private void onDeadlineTimeoutReached(final @NotNull SentryDate finishTimestamp) { forceFinish( - (status != null) ? status : SpanStatus.DEADLINE_EXCEEDED, - transactionOptions.getIdleTimeout() != null, - null); + getDeadlineStatus(), transactionOptions.getIdleTimeout() != null, null, finishTimestamp); isDeadlineTimerRunning.set(false); } + /** The deadline keeps a status the transaction already has. */ + private @NotNull SpanStatus getDeadlineStatus() { + final @Nullable SpanStatus status = getStatus(); + return (status != null) ? status : SpanStatus.DEADLINE_EXCEEDED; + } + + /** + * Whether the deadline timeout has been reached, even if the deadline timer has not run yet. + * + *

Once it has, finishing the transaction in any way ends it at the deadline instead. + */ + @ApiStatus.Internal + public boolean hasDeadlinePassed() { + return deadline != null && deadline.hasPassed(); + } + + /** + * Ends the transaction the way the deadline timer would have on a device that stayed awake, if + * the deadline has passed. + * + *

The caller's hint and dropIfNoChildren still apply: they decide how the transaction is + * delivered, for example flushed to disk before a crash, not what it contains. + * + * @return whether the deadline has passed, so that the caller must not finish the transaction + */ + private boolean finishAtDeadlineIfPassed( + final boolean dropIfNoChildren, final @Nullable Hint hint) { + final @Nullable SentryDate deadlineTimestamp = this.deadlineTimestamp; + if (deadlineTimestamp == null || !hasDeadlinePassed()) { + return false; + } + forceFinish(getDeadlineStatus(), dropIfNoChildren, hint, deadlineTimestamp); + return true; + } + @Override public void forceFinish( final @NotNull SpanStatus status, final boolean dropIfNoChildren, final @Nullable Hint hint) { - if (isFinished()) { + if (finishAtDeadlineIfPassed(dropIfNoChildren, hint)) { return; } + forceFinish(status, dropIfNoChildren, hint, scopes.getOptions().getDateProvider().now()); + } - final @NotNull SentryDate finishTimestamp = scopes.getOptions().getDateProvider().now(); + private void forceFinish( + final @NotNull SpanStatus status, + final boolean dropIfNoChildren, + final @Nullable Hint hint, + final @NotNull SentryDate finishTimestamp) { + if (isFinished()) { + return; + } // abort all child-spans first, this ensures the transaction can be finished, // even if waitForChildren is true @@ -173,7 +249,7 @@ public void forceFinish( span.setSpanFinishedCallback(null); span.finish(status, finishTimestamp); } - finish(status, finishTimestamp, dropIfNoChildren, hint); + finishRoot(status, finishTimestamp, dropIfNoChildren, hint); } @Override @@ -182,6 +258,17 @@ public void finish( @Nullable SentryDate finishDate, boolean dropIfNoChildren, @Nullable Hint hint) { + if (finishAtDeadlineIfPassed(dropIfNoChildren, hint)) { + return; + } + finishRoot(status, finishDate, dropIfNoChildren, hint); + } + + private void finishRoot( + final @Nullable SpanStatus status, + final @Nullable SentryDate finishDate, + final boolean dropIfNoChildren, + final @Nullable Hint hint) { // try to get the high precision timestamp from the root span SentryDate finishTimestamp = root.getFinishDate(); @@ -204,7 +291,8 @@ public void finish( this.finishStatus = FinishStatus.finishing(status); if (!root.isFinished() - && (!transactionOptions.isWaitForChildren() || hasAllChildrenFinished())) { + && (!transactionOptions.isWaitForChildren() || hasAllChildrenFinished()) + && isRootFinishClaimed.compareAndSet(false, true)) { final @NotNull AtomicReference> performanceCollectionData = new AtomicReference<>(); @@ -304,18 +392,24 @@ private void cancelIdleTimer() { } private void scheduleDeadlineTimeout() { - final @Nullable Long deadlineTimeOut = transactionOptions.getDeadlineTimeout(); - if (deadlineTimeOut != null) { + final @Nullable Deadline deadline = this.deadline; + final @Nullable SentryDate deadlineTimestamp = this.deadlineTimestamp; + if (deadline != null && deadlineTimestamp != null) { try (final @NotNull ISentryLifecycleToken ignored = timerLock.acquire()) { if (timersEnabled) { cancelDeadlineTimer(); isDeadlineTimerRunning.set(true); try { + // The executor's delay stops while the device is suspended, while the deadline keeps + // counting, so this task can only run at or after the deadline. It needs no second + // check. deadlineTimeoutFuture = scopes .getOptions() .getTimerExecutorService() - .schedule(this::onDeadlineTimeoutReached, deadlineTimeOut); + .schedule( + () -> onDeadlineTimeoutReached(deadlineTimestamp), + deadline.remaining(TimeUnit.MILLISECONDS)); } catch (Throwable e) { scopes .getOptions() @@ -323,7 +417,7 @@ private void scheduleDeadlineTimeout() { .log(SentryLevel.WARNING, "Failed to schedule finish timer", e); // if we failed to schedule the finish timer for some reason, we finish it here right // away - onDeadlineTimeoutReached(); + onDeadlineTimeoutReached(scopes.getOptions().getDateProvider().now()); } } } @@ -454,6 +548,12 @@ private ISpan createChild( return NoOpSpan.getInstance(); } + // A span started now would start after the deadline ends the transaction. On a device that + // stayed awake the transaction would already be finished, which starts no span either. + if (finishAtDeadlineIfPassed(transactionOptions.getIdleTimeout() != null, null)) { + return NoOpSpan.getInstance(); + } + if (!this.instrumenter.equals(spanContext.getInstrumenter())) { return NoOpSpan.getInstance(); } diff --git a/sentry/src/test/java/io/sentry/SentryTracerTest.kt b/sentry/src/test/java/io/sentry/SentryTracerTest.kt index 20232f56b4d..9789167b2be 100644 --- a/sentry/src/test/java/io/sentry/SentryTracerTest.kt +++ b/sentry/src/test/java/io/sentry/SentryTracerTest.kt @@ -7,9 +7,15 @@ import io.sentry.protocol.TransactionNameSource import io.sentry.protocol.User import io.sentry.test.createTestScopes import io.sentry.test.getProperty +import io.sentry.time.MonotonicTicker +import io.sentry.time.TestMonotonicTicker import io.sentry.util.thread.IThreadChecker import java.time.LocalDateTime import java.time.ZoneOffset +import java.util.concurrent.Callable +import java.util.concurrent.Future +import java.util.concurrent.FutureTask +import java.util.concurrent.TimeUnit import kotlin.test.Test import kotlin.test.assertEquals import kotlin.test.assertFalse @@ -35,7 +41,12 @@ import org.mockito.kotlin.whenever class SentryTracerTest { private class Fixture { - val options = SentryOptions() + val ticker = TestMonotonicTicker() + // SentryOptions has no ticker setter. + val options = + object : SentryOptions() { + override fun getMonotonicTicker(): MonotonicTicker = ticker + } val scopes: Scopes val compositePerformanceCollector: CompositePerformanceCollector @@ -1870,4 +1881,166 @@ class SentryTracerTest { assertNull(transaction.getTag(null)) assertNull(transaction.getTag("k")) } + + @Test + fun `when the deadline timer runs late, the transaction and its open spans end at the deadline`() { + val timer = ManualTimer() + val clock = TestDateProvider() + val transaction = getSutWithDeadline(timer, clock) + val span = transaction.startChild("op") + + sleepFor(3, TimeUnit.HOURS, clock) + timer.run(DEADLINE_MILLIS) + + assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) + assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) + verify(fixture.scopes).captureTransaction(any(), anyOrNull(), anyOrNull(), anyOrNull()) + } + + @Test + fun `when finished after the deadline passed but before the deadline timer ran, the transaction ends at the deadline`() { + val timer = ManualTimer() + val clock = TestDateProvider() + val transaction = getSutWithDeadline(timer, clock) + val span = transaction.startChild("op") + + sleepFor(3, TimeUnit.HOURS, clock) + transaction.finish(SpanStatus.OK) + + assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) + assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) + verify(fixture.scopes).captureTransaction(any(), anyOrNull(), anyOrNull(), anyOrNull()) + } + + @Test + fun `when finished after the deadline passed, the transaction keeps a status it already had`() { + val transaction = getSutWithDeadline(ManualTimer(), TestDateProvider()) + transaction.startChild("op") + transaction.status = SpanStatus.UNAVAILABLE + + fixture.ticker.advance(3, TimeUnit.HOURS) + transaction.finish(SpanStatus.OK) + + assertThat(transaction.status).isEqualTo(SpanStatus.UNAVAILABLE) + } + + @Test + fun `when the idle timeout runs after the deadline passed, the transaction ends at the deadline`() { + val timer = ManualTimer() + val clock = TestDateProvider() + val transaction = getSutWithDeadline(timer, clock, idleTimeout = IDLE_MILLIS) + val span = transaction.startChild("open") + // schedules the idle timeout, since the transaction doesn't wait for children + transaction.startChild("finished").finish() + + sleepFor(3, TimeUnit.HOURS, clock) + timer.run(IDLE_MILLIS) + + assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) + } + + @Test + fun `when force finished after the deadline passed, the transaction ends at the deadline with the hint`() { + val clock = TestDateProvider() + val transaction = getSutWithDeadline(ManualTimer(), clock) + transaction.startChild("op") + val hint = Hint() + + sleepFor(3, TimeUnit.HOURS, clock) + transaction.forceFinish(SpanStatus.ABORTED, false, hint) + + assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) + verify(fixture.scopes).captureTransaction(any(), anyOrNull(), eq(hint), anyOrNull()) + } + + @Test + fun `when a span starts after the deadline passed, it is a no-op and the transaction ends at the deadline`() { + val clock = TestDateProvider() + val transaction = getSutWithDeadline(ManualTimer(), clock) + val span = transaction.startChild("op") + + sleepFor(3, TimeUnit.HOURS, clock) + val lateSpan = transaction.startChild("late") + + assertThat(lateSpan).isInstanceOf(NoOpSpan::class.java) + assertThat(transaction.isFinished).isTrue() + assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) + } + + @Test + fun `when finished before the deadline, the transaction ends now with its own status`() { + val clock = TestDateProvider() + val transaction = getSutWithDeadline(ManualTimer(), clock) + val span = transaction.startChild("op") + + sleepFor(DEADLINE_MILLIS - 1, TimeUnit.MILLISECONDS, clock) + span.finish(SpanStatus.OK) + transaction.finish(SpanStatus.OK) + + assertThat(transaction.status).isEqualTo(SpanStatus.OK) + assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.now().nanoTimestamp()) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.now().nanoTimestamp()) + } + + private fun getSutWithDeadline( + timer: ManualTimer, + clock: TestDateProvider, + idleTimeout: Long? = null, + ): SentryTracer = + fixture.getSut( + optionsConfiguration = { + it.timerExecutorService = timer + it.dateProvider = clock + }, + idleTimeout = idleTimeout, + deadlineTimeout = DEADLINE_MILLIS, + ) + + /** Moves both clocks on, as a device does across a suspend that the timers don't notice. */ + private fun sleepFor(amount: Long, unit: TimeUnit, clock: TestDateProvider) { + fixture.ticker.advance(amount, unit) + clock.nowNanos += unit.toNanos(amount) + } + + private class TestDateProvider : SentryDateProvider { + var nowNanos = START_NANOS + + override fun now(): SentryDate = SentryLongDate(nowNanos) + + fun deadlineNanos(): Long = START_NANOS + TimeUnit.MILLISECONDS.toNanos(DEADLINE_MILLIS) + } + + /** Holds scheduled tasks by their delay instead of running them, so a test runs each one. */ + private class ManualTimer : ISentryExecutorService { + private val tasks = mutableMapOf() + + fun run(delayMillis: Long) = tasks.getValue(delayMillis).run() + + override fun schedule(runnable: Runnable, delayMillis: Long): Future<*> { + tasks[delayMillis] = runnable + return FutureTask {} + } + + override fun submit(runnable: Runnable): Future<*> = FutureTask {} + + override fun submit(callable: Callable): Future = FutureTask(callable) + + override fun close(timeoutMillis: Long) {} + + override fun isClosed(): Boolean = false + } + + private companion object { + const val START_NANOS = 1_000_000_000_000L + const val DEADLINE_MILLIS = 30_000L + const val IDLE_MILLIS = 3_000L + } } From c8803435758bb028f9f81c23fd5040b5a12599d4 Mon Sep 17 00:00:00 2001 From: Nelson Osacky Date: Thu, 12 Nov 2026 14:58:20 +0100 Subject: [PATCH 2/5] changelog Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 1e05874449d..856ca4dfbbd 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,7 @@ ### Fixes - Android: Count deep sleep in breadcrumb, screenshot and view hierarchy debounce windows, so the first low-memory or battery breadcrumb after a long Doze is no longer dropped ([#6590](https://github.com/getsentry/sentry-java/pull/6590)) +- Android: End `ui.load` transactions at their deadline as `deadline_exceeded` when the device slept or the app was frozen, instead of reporting TTID, TTFD and app start values that are hours long ([#6599](https://github.com/getsentry/sentry-java/pull/6599)) ## 8.64.0 From 49801b0428b95e201f4016df3d349c24ca14d94a Mon Sep 17 00:00:00 2001 From: Nelson Osacky Date: Thu, 12 Nov 2026 15:24:54 +0100 Subject: [PATCH 3/5] ref(core): Return a no-op span after the deadline without finishing Starting a span after the deadline finished and captured the whole transaction on the thread that started the span, which may hold a lock. Return the no-op span only: the overdue deadline timer ends the transaction at the deadline right after. Co-Authored-By: Claude Opus 5.5 --- sentry/src/main/java/io/sentry/SentryTracer.java | 7 ++++--- sentry/src/test/java/io/sentry/SentryTracerTest.kt | 12 +++++++++--- 2 files changed, 13 insertions(+), 6 deletions(-) diff --git a/sentry/src/main/java/io/sentry/SentryTracer.java b/sentry/src/main/java/io/sentry/SentryTracer.java index 55f513bc0d9..a9d8717bd73 100644 --- a/sentry/src/main/java/io/sentry/SentryTracer.java +++ b/sentry/src/main/java/io/sentry/SentryTracer.java @@ -548,9 +548,10 @@ private ISpan createChild( return NoOpSpan.getInstance(); } - // A span started now would start after the deadline ends the transaction. On a device that - // stayed awake the transaction would already be finished, which starts no span either. - if (finishAtDeadlineIfPassed(transactionOptions.getIdleTimeout() != null, null)) { + // A span started now would start after the deadline the transaction ends at. On a device that + // stayed awake the transaction would already be finished. The overdue deadline timer finishes + // it, rather than this thread, which may be holding a lock. + if (hasDeadlinePassed()) { return NoOpSpan.getInstance(); } diff --git a/sentry/src/test/java/io/sentry/SentryTracerTest.kt b/sentry/src/test/java/io/sentry/SentryTracerTest.kt index 9789167b2be..ffebd1bdc81 100644 --- a/sentry/src/test/java/io/sentry/SentryTracerTest.kt +++ b/sentry/src/test/java/io/sentry/SentryTracerTest.kt @@ -1961,18 +1961,24 @@ class SentryTracerTest { } @Test - fun `when a span starts after the deadline passed, it is a no-op and the transaction ends at the deadline`() { + fun `when a span starts after the deadline passed, it is a no-op and the deadline timer ends the transaction`() { + val timer = ManualTimer() val clock = TestDateProvider() - val transaction = getSutWithDeadline(ManualTimer(), clock) + val transaction = getSutWithDeadline(timer, clock) val span = transaction.startChild("op") sleepFor(3, TimeUnit.HOURS, clock) val lateSpan = transaction.startChild("late") assertThat(lateSpan).isInstanceOf(NoOpSpan::class.java) - assertThat(transaction.isFinished).isTrue() + assertThat(transaction.isFinished).isFalse() + + timer.run(DEADLINE_MILLIS) + + assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) + assertThat(transaction.children).containsExactly(span) } @Test From 68d48d3a3bcc5bf22cd6d3465bc49f10554c9073 Mon Sep 17 00:00:00 2001 From: Nelson Osacky Date: Thu, 12 Nov 2026 16:06:20 +0100 Subject: [PATCH 4/5] fix(core): Change only the status of spans that finish after the deadline Timings now stay exactly as before: the deadline timer ends spans at now() again, spans started after the deadline are recorded, and the ActivityLifecycleIntegration and PerformanceAndroidEventProcessor changes are reverted. Instead, once the monotonic-ticker deadline has passed, Span.finish gives the transaction and any span that finishes after it the status the deadline timer gives: the transaction's own status, or DEADLINE_EXCEEDED. Late frames after a device sleep then no longer report ok, so span.status:ok filters them out. Co-Authored-By: Claude Opus 5.5 --- .../core/ActivityLifecycleIntegration.java | 57 +------- .../PerformanceAndroidEventProcessor.java | 21 +-- .../core/ActivityLifecycleIntegrationTest.kt | 102 +++++--------- .../PerformanceAndroidEventProcessorTest.kt | 24 +--- .../src/main/kotlin/io/sentry/test/Mocks.kt | 23 +++ sentry/api/sentry.api | 1 - .../src/main/java/io/sentry/SentryTracer.java | 126 ++++------------- sentry/src/main/java/io/sentry/Span.java | 6 +- .../test/java/io/sentry/SentryTracerTest.kt | 131 +++++------------- 9 files changed, 128 insertions(+), 363 deletions(-) diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java b/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java index 4c318538b63..0c3b7d8d5ff 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java @@ -25,7 +25,6 @@ import io.sentry.SentryLevel; import io.sentry.SentryNanotimeDate; import io.sentry.SentryOptions; -import io.sentry.SentryTracer; import io.sentry.SpanOptions; import io.sentry.SpanStatus; import io.sentry.TracesSamplingDecision; @@ -523,7 +522,6 @@ private void finishTransaction( final @Nullable ISpan ttidSpan, final @Nullable ISpan ttfdSpan) { if (transaction != null) { - finishTransactionIfDeadlinePassed(transaction, ttidSpan, ttfdSpan); // if io.sentry.traces.activity.auto-finish.enable is disabled, transaction may be already // finished manually when this method is called. if (transaction.isFinished()) { @@ -583,7 +581,6 @@ public void onActivityCreated( scopes.configureScope(scope -> scope.setScreen(activityClassName)); } startTracing(activity); - final @Nullable ITransaction transaction = activitiesWithOngoingTransactions.get(activity); final @Nullable ISpan ttidSpan = ttidSpanMap.get(activity); final @Nullable ISpan ttfdSpan = ttfdSpanMap.get(activity); @@ -594,7 +591,7 @@ public void onActivityCreated( && ttfdSpan != null && fullyDisplayedReporter != null) { fullyDisplayedReporter.registerFullyDrawnListener( - () -> onFullFrameDrawn(transaction, ttidSpan, ttfdSpan)); + () -> onFullFrameDrawn(ttidSpan, ttfdSpan)); } } } @@ -657,19 +654,15 @@ public void onActivityResumed(final @NotNull Activity activity) { } if (performanceEnabled) { - final @Nullable ITransaction transaction = activitiesWithOngoingTransactions.get(activity); final @Nullable ISpan ttidSpan = ttidSpanMap.get(activity); final @Nullable ISpan ttfdSpan = ttfdSpanMap.get(activity); if (activity.getWindow() != null) { FirstDrawDoneListener.registerForNextDraw( - activity, - () -> onFirstFrameDrawn(transaction, ttfdSpan, ttidSpan), - buildInfoProvider); + activity, () -> onFirstFrameDrawn(ttfdSpan, ttidSpan), buildInfoProvider); } else { // Posting a task to the main thread's handler will make it executed after it finished // its current job. That is, right after the activity draws the layout. - new Handler(Looper.getMainLooper()) - .post(() -> onFirstFrameDrawn(transaction, ttfdSpan, ttidSpan)); + new Handler(Looper.getMainLooper()).post(() -> onFirstFrameDrawn(ttfdSpan, ttidSpan)); } } } @@ -722,10 +715,6 @@ public void onActivityDestroyed(final @NotNull Activity activity) { helper.clear(); } if (performanceEnabled) { - final ISpan ttidSpan = ttidSpanMap.get(activity); - final ISpan ttfdSpan = ttfdSpanMap.get(activity); - finishTransactionIfDeadlinePassed( - activitiesWithOngoingTransactions.get(activity), ttidSpan, ttfdSpan); // in case the appStartSpan isn't completed yet, we finish it as cancelled to avoid // memory leak @@ -735,6 +724,8 @@ public void onActivityDestroyed(final @NotNull Activity activity) { } // we finish the ttidSpan as cancelled in case it isn't completed yet + final ISpan ttidSpan = ttidSpanMap.get(activity); + final ISpan ttfdSpan = ttfdSpanMap.get(activity); finishSpan(ttidSpan, SpanStatus.DEADLINE_EXCEEDED); // we finish the ttfdSpan as deadline_exceeded in case it isn't completed yet @@ -805,12 +796,7 @@ private void cancelTtfdAutoClose() { } } - private void onFirstFrameDrawn( - final @Nullable ITransaction transaction, - final @Nullable ISpan ttfdSpan, - final @Nullable ISpan ttidSpan) { - finishTransactionIfDeadlinePassed(transaction, ttidSpan, ttfdSpan); - + private void onFirstFrameDrawn(final @Nullable ISpan ttfdSpan, final @Nullable ISpan ttidSpan) { // app start span final @NotNull AppStartMetrics appStartMetrics = AppStartMetrics.getInstance(); final @NotNull TimeSpan appStartTimeSpan = appStartMetrics.getAppStartTimeSpan(); @@ -867,11 +853,7 @@ private void stopTimeSpanAtDate( } } - private void onFullFrameDrawn( - final @Nullable ITransaction transaction, - final @NotNull ISpan ttidSpan, - final @NotNull ISpan ttfdSpan) { - finishTransactionIfDeadlinePassed(transaction, ttidSpan, ttfdSpan); + private void onFullFrameDrawn(final @NotNull ISpan ttidSpan, final @NotNull ISpan ttfdSpan) { cancelTtfdAutoClose(); // Sentry.reportFullyDisplayed can be run in any thread, so we have to ensure synchronization // with first frame drawn @@ -896,31 +878,6 @@ private void onFullFrameDrawn( } } - /** - * Ends the transaction at its deadline if that has passed, because the device slept or the - * process was frozen before the deadline timer could run. - * - *

On a device that stayed awake the deadline timer would have ended the transaction and its - * spans before the activity callback that calls this. Ending them here first lets the callback - * carry on as it would have there: its spans are finished, so it measures nothing. - */ - private void finishTransactionIfDeadlinePassed( - final @Nullable ITransaction transaction, - final @Nullable ISpan ttidSpan, - final @Nullable ISpan ttfdSpan) { - if (!(transaction instanceof SentryTracer) - || !((SentryTracer) transaction).hasDeadlinePassed()) { - return; - } - // When the TTFD auto-close is due before the deadline, on that device it had already ended the - // TTFD span. - if (options != null && TTFD_TIMEOUT_MILLIS < options.getDeadlineTimeout()) { - finishExceededTtfdSpan(ttfdSpan, ttidSpan); - } - // Past the deadline, finishing ends the transaction at the deadline, with its status. - transaction.finish(); - } - private void finishExceededTtfdSpan( final @Nullable ISpan ttfdSpan, final @Nullable ISpan ttidSpan) { if (ttfdSpan == null || ttfdSpan.isFinished()) { diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/PerformanceAndroidEventProcessor.java b/sentry-android-core/src/main/java/io/sentry/android/core/PerformanceAndroidEventProcessor.java index 37e1a0a0396..503bd1d856b 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/PerformanceAndroidEventProcessor.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/PerformanceAndroidEventProcessor.java @@ -100,8 +100,7 @@ public SentryEvent process(@NotNull SentryEvent event, @NotNull Hint hint) { && isStandaloneAppStartTxn && !traceContext.getData().containsKey(APP_START_SCREEN_DATA); - if (appStartMetrics.shouldSendStartMeasurements(isHeadlessStandaloneAppStartTxn) - && !isAppStartSpanCutShort(transaction)) { + if (appStartMetrics.shouldSendStartMeasurements(isHeadlessStandaloneAppStartTxn)) { final @NotNull TimeSpan appStartTimeSpan = isHeadlessStandaloneAppStartTxn ? appStartMetrics.getAppStartTimeSpanForHeadless() @@ -292,24 +291,6 @@ private boolean hasAppStartSpan(final @NotNull SentryTransaction txn) { return context != null && context.getOperation().equals(STANDALONE_APP_START_OP); } - /** - * Whether something ended the app.start span before the first frame did, such as the deadline or - * the activity being destroyed. - * - *

On a device that stays awake the app start time span is still running then, so nothing is - * measured. After the device slept or the process was frozen, a first frame drawn since may - * already have stopped it, hours after the app.start span ended. - */ - private static boolean isAppStartSpanCutShort(final @NotNull SentryTransaction txn) { - for (final @NotNull SentrySpan span : txn.getSpans()) { - if (span.getOp().contentEquals(APP_START_COLD) - || span.getOp().contentEquals(APP_START_WARM)) { - return span.getStatus() != SpanStatus.OK; - } - } - return false; - } - private void attachAppStartSpans( final @NotNull AppStartMetrics appStartMetrics, final @NotNull AppStartMetrics.AppStartType appStartType, diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt index 27c2783cc96..931a171e480 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt +++ b/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt @@ -44,6 +44,7 @@ import io.sentry.protocol.MeasurementValue import io.sentry.protocol.SentryId import io.sentry.protocol.TransactionNameSource import io.sentry.test.DeferredExecutorService +import io.sentry.test.ManualTimerExecutorService import io.sentry.test.getProperty import io.sentry.time.TestMonotonicTicker import java.util.concurrent.Future @@ -2567,8 +2568,12 @@ class ActivityLifecycleIntegrationTest { } @Test - fun `first frame drawn after the deadline passed ends the transaction at the deadline without TTID`() { - val sut = fixture.getSut { it.tracesSampleRate = 1.0 } + fun `first frame drawn after the deadline passed changes only the status`() { + val timer = ManualTimerExecutorService() + val sut = fixture.getSut { + it.tracesSampleRate = 1.0 + it.timerExecutorService = timer + } var nowMillis = START_MILLIS fixture.options.dateProvider = SentryDateProvider { SentryNanotimeDate(nowMillis, 0) } setAppStartTime(SentryNanotimeDate(START_MILLIS, 0)) @@ -2582,51 +2587,23 @@ class ActivityLifecycleIntegrationTest { fixture.ticker.advance(3, TimeUnit.HOURS) nowMillis += TimeUnit.HOURS.toMillis(3) runFirstDraw(view) + timer.runScheduled(fixture.options.idleTimeout!!) - for (span in listOf(fixture.transaction, ttidSpan, appStartSpan)) { + val firstFrameNanos = TimeUnit.MILLISECONDS.toNanos(nowMillis) + for (span in listOf(ttidSpan, appStartSpan)) { assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) - assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(deadlineNanos()) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(firstFrameNanos) } - assertThat((ttidSpan as Span).measurements).isEmpty() - verify(fixture.scopes) - .captureTransaction( - check { - assertThat(it.measurements) - .doesNotContainKey(MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY) - }, - anyOrNull(), - anyOrNull(), - anyOrNull(), - ) - } - - @Test - fun `first frame drawn before the deadline still measures TTID`() { - val sut = fixture.getSut { it.tracesSampleRate = 1.0 } - var nowMillis = START_MILLIS - fixture.options.dateProvider = SentryDateProvider { SentryNanotimeDate(nowMillis, 0) } - setAppStartTime(SentryNanotimeDate(START_MILLIS, 0)) - sut.register(fixture.scopes, fixture.options) - val view = fixture.createView() - val activity = createAndResumeActivity(sut, view) - val ttidSpan = sut.ttidSpanMap[activity]!! - - fixture.ticker.advance(29, TimeUnit.SECONDS) - nowMillis += TimeUnit.SECONDS.toMillis(29) - runFirstDraw(view) - - assertThat(ttidSpan.status).isEqualTo(SpanStatus.OK) - assertThat(ttidSpan.finishDate!!.nanoTimestamp()) - .isEqualTo(TimeUnit.MILLISECONDS.toNanos(nowMillis)) assertThat( (ttidSpan as Span).measurements[MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY]!!.value ) - .isEqualTo(TimeUnit.SECONDS.toMillis(29)) - assertThat(fixture.transaction.isFinished).isFalse() + .isEqualTo(TimeUnit.HOURS.toMillis(3)) + assertThat(fixture.transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(fixture.transaction.finishDate!!.nanoTimestamp()).isEqualTo(firstFrameNanos) } @Test - fun `full display reported after the deadline passed ends the TTFD span as its auto-close would, without TTFD`() { + fun `full display reported after the deadline passed changes only the status`() { val sut = fixture.getSut { it.tracesSampleRate = 1.0 it.isEnableTimeToFullDisplayTracing = true @@ -2637,51 +2614,42 @@ class ActivityLifecycleIntegrationTest { sut.register(fixture.scopes, fixture.options) val view = fixture.createView() val activity = createAndResumeActivity(sut, view) - val ttidSpan = sut.ttidSpanMap[activity]!! val ttfdSpan = sut.ttfdSpanMap[activity]!! - nowMillis += 1_000 runFirstDraw(view) - // the device sleeps before the app reports full display, and the timers haven't run yet fixture.ticker.advance(3, TimeUnit.HOURS) nowMillis += TimeUnit.HOURS.toMillis(3) fixture.options.fullyDisplayedReporter.reportFullyDrawn() assertThat(ttfdSpan.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) - assertThat(ttfdSpan.finishDate).isEqualTo(ttidSpan.finishDate) - assertThat(ttfdSpan.description).endsWith(" - Deadline Exceeded") - assertThat((ttfdSpan as Span).measurements).isEmpty() - assertThat(fixture.transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) - verify(fixture.scopes) - .captureTransaction( - check { - assertThat(it.measurements).doesNotContainKey(MeasurementValue.KEY_TIME_TO_FULL_DISPLAY) - }, - anyOrNull(), - anyOrNull(), - anyOrNull(), - ) + assertThat(ttfdSpan.finishDate!!.nanoTimestamp()) + .isEqualTo(TimeUnit.MILLISECONDS.toNanos(nowMillis)) + assertThat((ttfdSpan as Span).measurements[MeasurementValue.KEY_TIME_TO_FULL_DISPLAY]!!.value) + .isEqualTo(TimeUnit.HOURS.toMillis(3)) } @Test - fun `activity destroyed after the deadline passed ends the transaction at the deadline`() { + fun `first frame drawn before the deadline keeps its status`() { val sut = fixture.getSut { it.tracesSampleRate = 1.0 } var nowMillis = START_MILLIS fixture.options.dateProvider = SentryDateProvider { SentryNanotimeDate(nowMillis, 0) } setAppStartTime(SentryNanotimeDate(START_MILLIS, 0)) sut.register(fixture.scopes, fixture.options) - val activity = createAndResumeActivity(sut, fixture.createView()) + val view = fixture.createView() + val activity = createAndResumeActivity(sut, view) val ttidSpan = sut.ttidSpanMap[activity]!! - val appStartSpan = sut.appStartSpan!! - fixture.ticker.advance(3, TimeUnit.HOURS) - nowMillis += TimeUnit.HOURS.toMillis(3) - sut.onActivityDestroyed(activity) + fixture.ticker.advance(29, TimeUnit.SECONDS) + nowMillis += TimeUnit.SECONDS.toMillis(29) + runFirstDraw(view) - for (span in listOf(fixture.transaction, ttidSpan, appStartSpan)) { - assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) - assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(deadlineNanos()) - } + assertThat(ttidSpan.status).isEqualTo(SpanStatus.OK) + assertThat(ttidSpan.finishDate!!.nanoTimestamp()) + .isEqualTo(TimeUnit.MILLISECONDS.toNanos(nowMillis)) + assertThat( + (ttidSpan as Span).measurements[MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY]!!.value + ) + .isEqualTo(TimeUnit.SECONDS.toMillis(29)) } private fun createAndResumeActivity(sut: ActivityLifecycleIntegration, view: View): Activity { @@ -2692,12 +2660,6 @@ class ActivityLifecycleIntegrationTest { return activity } - /** Where the deadline ends a ui.load that started at [START_MILLIS]. */ - private fun deadlineNanos(): Long = - TimeUnit.MILLISECONDS.toNanos( - START_MILLIS + TransactionOptions.DEFAULT_DEADLINE_TIMEOUT_AUTO_TRANSACTION - ) - private fun SentryTracer.isFinishing() = getProperty("finishStatus").getProperty("isFinishing") diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/PerformanceAndroidEventProcessorTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/PerformanceAndroidEventProcessorTest.kt index fa433e0b6f4..0ab922fc32a 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/PerformanceAndroidEventProcessorTest.kt +++ b/sentry-android-core/src/test/java/io/sentry/android/core/PerformanceAndroidEventProcessorTest.kt @@ -67,11 +67,7 @@ class PerformanceAndroidEventProcessorTest { private val fixture = Fixture() - private fun createAppStartSpan( - traceId: SentryId, - coldStart: Boolean = true, - status: SpanStatus = SpanStatus.OK, - ) = + private fun createAppStartSpan(traceId: SentryId, coldStart: Boolean = true) = SentrySpan( 0.0, 1.0, @@ -80,7 +76,7 @@ class PerformanceAndroidEventProcessorTest { null, if (coldStart) APP_START_COLD else APP_START_WARM, "App Start", - status, + SpanStatus.OK, null, emptyMap(), emptyMap(), @@ -461,22 +457,6 @@ class PerformanceAndroidEventProcessorTest { assertFalse(tr.measurements.containsKey(MeasurementValue.KEY_APP_START_WARM)) } - @Test - fun `app start that the deadline ended before the first frame adds no measurement`() { - val sut = fixture.getSut() - var tr = createUiLoadTransaction() - tr.spans.add( - createAppStartSpan(tr.contexts.trace!!.traceId, status = SpanStatus.DEADLINE_EXCEEDED) - ) - // a first frame drawn after the device slept stopped the app start time span - setAppStart(fixture.options) - - tr = sut.process(tr, Hint()) - - assertThat(tr.measurements).doesNotContainKey(MeasurementValue.KEY_APP_START_COLD) - assertThat(tr.spans.map { it.op }).containsExactly(APP_START_COLD) - } - @Test fun `add cold start measurement for performance-v2`() { val sut = fixture.getSut(enablePerformanceV2 = true) diff --git a/sentry-test-support/src/main/kotlin/io/sentry/test/Mocks.kt b/sentry-test-support/src/main/kotlin/io/sentry/test/Mocks.kt index b66c0f29475..41b4baae64a 100644 --- a/sentry-test-support/src/main/kotlin/io/sentry/test/Mocks.kt +++ b/sentry-test-support/src/main/kotlin/io/sentry/test/Mocks.kt @@ -75,6 +75,29 @@ class DeferredExecutorService : ISentryExecutorService { fun hasScheduledRunnables(): Boolean = scheduledRunnables.isNotEmpty() } +/** + * Keeps the latest task scheduled with each delay instead of running it, so a test can run one + * timer, such as an idle timeout, while another, such as a deadline, stays pending. + */ +class ManualTimerExecutorService : ISentryExecutorService { + private val scheduled = mutableMapOf() + + fun runScheduled(delayMillis: Long) = synchronized(this) { scheduled.getValue(delayMillis) }.run() + + override fun schedule(runnable: Runnable, delayMillis: Long): Future<*> { + synchronized(this) { scheduled[delayMillis] = runnable } + return FutureTask {} + } + + override fun submit(runnable: Runnable): Future<*> = FutureTask {} + + override fun submit(callable: Callable): Future = FutureTask(callable) + + override fun close(timeoutMillis: Long) {} + + override fun isClosed(): Boolean = false +} + class NonOverridableNoOpSentryExecutorService : ISentryExecutorService { // mirrors NoOpSentryExecutorService: a task that is never run is reported as cancelled, so // callers can tell it apart from a queued one diff --git a/sentry/api/sentry.api b/sentry/api/sentry.api index 2b7e530a8cc..dfce80a93d8 100644 --- a/sentry/api/sentry.api +++ b/sentry/api/sentry.api @@ -4377,7 +4377,6 @@ public final class io/sentry/SentryTracer : io/sentry/ITransaction { public fun getTag (Ljava/lang/String;)Ljava/lang/String; public fun getThrowable ()Ljava/lang/Throwable; public fun getTransactionNameSource ()Lio/sentry/protocol/TransactionNameSource; - public fun hasDeadlinePassed ()Z public fun isFinished ()Z public fun isNoOp ()Z public fun isProfileSampled ()Ljava/lang/Boolean; diff --git a/sentry/src/main/java/io/sentry/SentryTracer.java b/sentry/src/main/java/io/sentry/SentryTracer.java index a9d8717bd73..a4f527f0f58 100644 --- a/sentry/src/main/java/io/sentry/SentryTracer.java +++ b/sentry/src/main/java/io/sentry/SentryTracer.java @@ -55,19 +55,10 @@ public final class SentryTracer implements ITransaction { * When the deadline timeout is reached, or null without one. * *

The deadline timer counts on a clock that stops while an Android device is suspended, so it - * can run hours late. After the process was frozen it is overdue and races the app's own threads. - * This deadline keeps counting through both, so whichever path finishes the transaction can tell - * that the deadline has passed, and end it where the timer would have on a device that stayed - * awake. + * runs late after the device slept, and after the process was frozen the app's own threads can + * finish spans before it. This deadline keeps counting through both. */ - private final @Nullable Deadline deadline; - - /** The wall time at which {@link #deadline} passes, and where the deadline ends the spans. */ - private final @Nullable SentryDate deadlineTimestamp; - - // After a thaw the overdue deadline timer and the app's threads can finish the transaction at the - // same moment, and it must be captured only once. - private final @NotNull AtomicBoolean isRootFinishClaimed = new AtomicBoolean(false); + private volatile @Nullable Deadline deadline; private @NotNull TransactionNameSource transactionNameSource; private final @NotNull Instrumenter instrumenter; @@ -119,21 +110,6 @@ public SentryTracer( this.compositePerformanceCollector.start(this); } - final @Nullable Long deadlineTimeout = transactionOptions.getDeadlineTimeout(); - if (deadlineTimeout != null) { - final @NotNull SentryOptions options = scopes.getOptions(); - this.deadline = - Deadline.after(options.getMonotonicTicker(), deadlineTimeout, TimeUnit.MILLISECONDS); - // Read from the date provider like every other span timestamp, so that they compare. - this.deadlineTimestamp = - new SentryLongDate( - options.getDateProvider().now().nanoTimestamp() - + TimeUnit.MILLISECONDS.toNanos(deadlineTimeout)); - } else { - this.deadline = null; - this.deadlineTimestamp = null; - } - if (transactionOptions.getIdleTimeout() != null || transactionOptions.getDeadlineTimeout() != null) { timersEnabled = true; @@ -179,65 +155,33 @@ private void onIdleTimeoutReached() { isIdleFinishTimerRunning.set(false); } - private void onDeadlineTimeoutReached(final @NotNull SentryDate finishTimestamp) { - forceFinish( - getDeadlineStatus(), transactionOptions.getIdleTimeout() != null, null, finishTimestamp); + private void onDeadlineTimeoutReached() { + forceFinish(getDeadlineStatus(), transactionOptions.getIdleTimeout() != null, null); isDeadlineTimerRunning.set(false); } - /** The deadline keeps a status the transaction already has. */ - private @NotNull SpanStatus getDeadlineStatus() { - final @Nullable SpanStatus status = getStatus(); - return (status != null) ? status : SpanStatus.DEADLINE_EXCEEDED; - } - - /** - * Whether the deadline timeout has been reached, even if the deadline timer has not run yet. - * - *

Once it has, finishing the transaction in any way ends it at the deadline instead. - */ - @ApiStatus.Internal - public boolean hasDeadlinePassed() { + /** Whether the deadline timeout has been reached, even if the deadline timer has not run yet. */ + boolean hasDeadlinePassed() { + final @Nullable Deadline deadline = this.deadline; return deadline != null && deadline.hasPassed(); } - /** - * Ends the transaction the way the deadline timer would have on a device that stayed awake, if - * the deadline has passed. - * - *

The caller's hint and dropIfNoChildren still apply: they decide how the transaction is - * delivered, for example flushed to disk before a crash, not what it contains. - * - * @return whether the deadline has passed, so that the caller must not finish the transaction - */ - private boolean finishAtDeadlineIfPassed( - final boolean dropIfNoChildren, final @Nullable Hint hint) { - final @Nullable SentryDate deadlineTimestamp = this.deadlineTimestamp; - if (deadlineTimestamp == null || !hasDeadlinePassed()) { - return false; - } - forceFinish(getDeadlineStatus(), dropIfNoChildren, hint, deadlineTimestamp); - return true; + /** The status the deadline gives: the transaction's own, if it has one. */ + @NotNull + SpanStatus getDeadlineStatus() { + final @Nullable SpanStatus status = getStatus(); + return (status != null) ? status : SpanStatus.DEADLINE_EXCEEDED; } @Override public void forceFinish( final @NotNull SpanStatus status, final boolean dropIfNoChildren, final @Nullable Hint hint) { - if (finishAtDeadlineIfPassed(dropIfNoChildren, hint)) { - return; - } - forceFinish(status, dropIfNoChildren, hint, scopes.getOptions().getDateProvider().now()); - } - - private void forceFinish( - final @NotNull SpanStatus status, - final boolean dropIfNoChildren, - final @Nullable Hint hint, - final @NotNull SentryDate finishTimestamp) { if (isFinished()) { return; } + final @NotNull SentryDate finishTimestamp = scopes.getOptions().getDateProvider().now(); + // abort all child-spans first, this ensures the transaction can be finished, // even if waitForChildren is true // iterate in reverse order to ensure leaf spans are processed before their parents @@ -249,7 +193,7 @@ private void forceFinish( span.setSpanFinishedCallback(null); span.finish(status, finishTimestamp); } - finishRoot(status, finishTimestamp, dropIfNoChildren, hint); + finish(status, finishTimestamp, dropIfNoChildren, hint); } @Override @@ -258,17 +202,6 @@ public void finish( @Nullable SentryDate finishDate, boolean dropIfNoChildren, @Nullable Hint hint) { - if (finishAtDeadlineIfPassed(dropIfNoChildren, hint)) { - return; - } - finishRoot(status, finishDate, dropIfNoChildren, hint); - } - - private void finishRoot( - final @Nullable SpanStatus status, - final @Nullable SentryDate finishDate, - final boolean dropIfNoChildren, - final @Nullable Hint hint) { // try to get the high precision timestamp from the root span SentryDate finishTimestamp = root.getFinishDate(); @@ -291,8 +224,7 @@ private void finishRoot( this.finishStatus = FinishStatus.finishing(status); if (!root.isFinished() - && (!transactionOptions.isWaitForChildren() || hasAllChildrenFinished()) - && isRootFinishClaimed.compareAndSet(false, true)) { + && (!transactionOptions.isWaitForChildren() || hasAllChildrenFinished())) { final @NotNull AtomicReference> performanceCollectionData = new AtomicReference<>(); @@ -392,24 +324,21 @@ private void cancelIdleTimer() { } private void scheduleDeadlineTimeout() { - final @Nullable Deadline deadline = this.deadline; - final @Nullable SentryDate deadlineTimestamp = this.deadlineTimestamp; - if (deadline != null && deadlineTimestamp != null) { + final @Nullable Long deadlineTimeOut = transactionOptions.getDeadlineTimeout(); + if (deadlineTimeOut != null) { try (final @NotNull ISentryLifecycleToken ignored = timerLock.acquire()) { if (timersEnabled) { cancelDeadlineTimer(); isDeadlineTimerRunning.set(true); + deadline = + Deadline.after( + scopes.getOptions().getMonotonicTicker(), deadlineTimeOut, TimeUnit.MILLISECONDS); try { - // The executor's delay stops while the device is suspended, while the deadline keeps - // counting, so this task can only run at or after the deadline. It needs no second - // check. deadlineTimeoutFuture = scopes .getOptions() .getTimerExecutorService() - .schedule( - () -> onDeadlineTimeoutReached(deadlineTimestamp), - deadline.remaining(TimeUnit.MILLISECONDS)); + .schedule(this::onDeadlineTimeoutReached, deadlineTimeOut); } catch (Throwable e) { scopes .getOptions() @@ -417,7 +346,7 @@ private void scheduleDeadlineTimeout() { .log(SentryLevel.WARNING, "Failed to schedule finish timer", e); // if we failed to schedule the finish timer for some reason, we finish it here right // away - onDeadlineTimeoutReached(scopes.getOptions().getDateProvider().now()); + onDeadlineTimeoutReached(); } } } @@ -548,13 +477,6 @@ private ISpan createChild( return NoOpSpan.getInstance(); } - // A span started now would start after the deadline the transaction ends at. On a device that - // stayed awake the transaction would already be finished. The overdue deadline timer finishes - // it, rather than this thread, which may be holding a lock. - if (hasDeadlinePassed()) { - return NoOpSpan.getInstance(); - } - if (!this.instrumenter.equals(spanContext.getInstrumenter())) { return NoOpSpan.getInstance(); } diff --git a/sentry/src/main/java/io/sentry/Span.java b/sentry/src/main/java/io/sentry/Span.java index 7ee7eed1900..b91978b18ff 100644 --- a/sentry/src/main/java/io/sentry/Span.java +++ b/sentry/src/main/java/io/sentry/Span.java @@ -196,7 +196,11 @@ public void finish(final @Nullable SpanStatus status, final @Nullable SentryDate return; } - this.context.setStatus(status); + // The deadline timer gives this status, but after the device slept or the process was frozen it + // runs late, and the app's own finish can come first. Either way the span outlived the + // deadline, and the status keeps it out of queries on span.status:ok. + this.context.setStatus( + transaction.hasDeadlinePassed() ? transaction.getDeadlineStatus() : status); this.timestamp = timestamp == null ? scopes.getOptions().getDateProvider().now() : timestamp; if (options.isTrimStart() || options.isTrimEnd()) { @Nullable SentryDate minChildStart = null; diff --git a/sentry/src/test/java/io/sentry/SentryTracerTest.kt b/sentry/src/test/java/io/sentry/SentryTracerTest.kt index ffebd1bdc81..feca8ad65f6 100644 --- a/sentry/src/test/java/io/sentry/SentryTracerTest.kt +++ b/sentry/src/test/java/io/sentry/SentryTracerTest.kt @@ -5,6 +5,7 @@ import io.sentry.profiling.ProfileRecordingState import io.sentry.protocol.SentryId import io.sentry.protocol.TransactionNameSource import io.sentry.protocol.User +import io.sentry.test.ManualTimerExecutorService import io.sentry.test.createTestScopes import io.sentry.test.getProperty import io.sentry.time.MonotonicTicker @@ -12,9 +13,6 @@ import io.sentry.time.TestMonotonicTicker import io.sentry.util.thread.IThreadChecker import java.time.LocalDateTime import java.time.ZoneOffset -import java.util.concurrent.Callable -import java.util.concurrent.Future -import java.util.concurrent.FutureTask import java.util.concurrent.TimeUnit import kotlin.test.Test import kotlin.test.assertEquals @@ -1883,121 +1881,83 @@ class SentryTracerTest { } @Test - fun `when the deadline timer runs late, the transaction and its open spans end at the deadline`() { - val timer = ManualTimer() + fun `when a span and the transaction finish after the deadline passed, only their status changes`() { val clock = TestDateProvider() - val transaction = getSutWithDeadline(timer, clock) - val span = transaction.startChild("op") - - sleepFor(3, TimeUnit.HOURS, clock) - timer.run(DEADLINE_MILLIS) - - assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) - assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) - assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) - assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) - verify(fixture.scopes).captureTransaction(any(), anyOrNull(), anyOrNull(), anyOrNull()) - } - - @Test - fun `when finished after the deadline passed but before the deadline timer ran, the transaction ends at the deadline`() { - val timer = ManualTimer() - val clock = TestDateProvider() - val transaction = getSutWithDeadline(timer, clock) + val transaction = getSutWithDeadline(ManualTimerExecutorService(), clock) val span = transaction.startChild("op") sleepFor(3, TimeUnit.HOURS, clock) + span.finish(SpanStatus.OK) transaction.finish(SpanStatus.OK) - assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) - assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) - assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) - verify(fixture.scopes).captureTransaction(any(), anyOrNull(), anyOrNull(), anyOrNull()) - } - - @Test - fun `when finished after the deadline passed, the transaction keeps a status it already had`() { - val transaction = getSutWithDeadline(ManualTimer(), TestDateProvider()) - transaction.startChild("op") - transaction.status = SpanStatus.UNAVAILABLE - - fixture.ticker.advance(3, TimeUnit.HOURS) - transaction.finish(SpanStatus.OK) - - assertThat(transaction.status).isEqualTo(SpanStatus.UNAVAILABLE) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.nowNanos) + assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.nowNanos) } @Test - fun `when the idle timeout runs after the deadline passed, the transaction ends at the deadline`() { - val timer = ManualTimer() + fun `when the idle timeout runs after the deadline passed, only the transaction status changes`() { + val timer = ManualTimerExecutorService() val clock = TestDateProvider() val transaction = getSutWithDeadline(timer, clock, idleTimeout = IDLE_MILLIS) - val span = transaction.startChild("open") // schedules the idle timeout, since the transaction doesn't wait for children - transaction.startChild("finished").finish() + transaction.startChild("op").finish() sleepFor(3, TimeUnit.HOURS, clock) - timer.run(IDLE_MILLIS) + timer.runScheduled(IDLE_MILLIS) assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) - assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) - assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) + assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.nowNanos) } @Test - fun `when force finished after the deadline passed, the transaction ends at the deadline with the hint`() { + fun `when force finished after the deadline passed, the transaction gets the deadline status`() { val clock = TestDateProvider() - val transaction = getSutWithDeadline(ManualTimer(), clock) - transaction.startChild("op") - val hint = Hint() + val transaction = getSutWithDeadline(ManualTimerExecutorService(), clock) + val span = transaction.startChild("op") sleepFor(3, TimeUnit.HOURS, clock) - transaction.forceFinish(SpanStatus.ABORTED, false, hint) + transaction.forceFinish(SpanStatus.ABORTED, false, null) assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) - assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) - verify(fixture.scopes).captureTransaction(any(), anyOrNull(), eq(hint), anyOrNull()) + assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.nowNanos) + assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.nowNanos) } @Test - fun `when a span starts after the deadline passed, it is a no-op and the deadline timer ends the transaction`() { - val timer = ManualTimer() - val clock = TestDateProvider() - val transaction = getSutWithDeadline(timer, clock) + fun `when spans finish after the deadline passed, they keep a status the transaction already has`() { + val transaction = getSutWithDeadline(ManualTimerExecutorService(), TestDateProvider()) val span = transaction.startChild("op") + transaction.status = SpanStatus.UNAVAILABLE - sleepFor(3, TimeUnit.HOURS, clock) - val lateSpan = transaction.startChild("late") - - assertThat(lateSpan).isInstanceOf(NoOpSpan::class.java) - assertThat(transaction.isFinished).isFalse() - - timer.run(DEADLINE_MILLIS) + fixture.ticker.advance(3, TimeUnit.HOURS) + span.finish(SpanStatus.OK) + transaction.finish(SpanStatus.OK) - assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) - assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) - assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.deadlineNanos()) - assertThat(transaction.children).containsExactly(span) + assertThat(span.status).isEqualTo(SpanStatus.UNAVAILABLE) + assertThat(transaction.status).isEqualTo(SpanStatus.UNAVAILABLE) } @Test - fun `when finished before the deadline, the transaction ends now with its own status`() { + fun `when spans finish before the deadline, they keep their own status`() { val clock = TestDateProvider() - val transaction = getSutWithDeadline(ManualTimer(), clock) + val transaction = getSutWithDeadline(ManualTimerExecutorService(), clock) val span = transaction.startChild("op") sleepFor(DEADLINE_MILLIS - 1, TimeUnit.MILLISECONDS, clock) span.finish(SpanStatus.OK) transaction.finish(SpanStatus.OK) + assertThat(span.status).isEqualTo(SpanStatus.OK) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.nowNanos) assertThat(transaction.status).isEqualTo(SpanStatus.OK) - assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.now().nanoTimestamp()) - assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.now().nanoTimestamp()) + assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.nowNanos) } private fun getSutWithDeadline( - timer: ManualTimer, + timer: ManualTimerExecutorService, clock: TestDateProvider, idleTimeout: Long? = null, ): SentryTracer = @@ -2017,35 +1977,12 @@ class SentryTracerTest { } private class TestDateProvider : SentryDateProvider { - var nowNanos = START_NANOS + var nowNanos = 1_000_000_000_000L override fun now(): SentryDate = SentryLongDate(nowNanos) - - fun deadlineNanos(): Long = START_NANOS + TimeUnit.MILLISECONDS.toNanos(DEADLINE_MILLIS) - } - - /** Holds scheduled tasks by their delay instead of running them, so a test runs each one. */ - private class ManualTimer : ISentryExecutorService { - private val tasks = mutableMapOf() - - fun run(delayMillis: Long) = tasks.getValue(delayMillis).run() - - override fun schedule(runnable: Runnable, delayMillis: Long): Future<*> { - tasks[delayMillis] = runnable - return FutureTask {} - } - - override fun submit(runnable: Runnable): Future<*> = FutureTask {} - - override fun submit(callable: Callable): Future = FutureTask(callable) - - override fun close(timeoutMillis: Long) {} - - override fun isClosed(): Boolean = false } private companion object { - const val START_NANOS = 1_000_000_000_000L const val DEADLINE_MILLIS = 30_000L const val IDLE_MILLIS = 3_000L } From fb766f2ca74eac664c3e820e2dd7917472e1e148 Mon Sep 17 00:00:00 2001 From: Nelson Osacky Date: Thu, 12 Nov 2026 16:06:20 +0100 Subject: [PATCH 5/5] changelog Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 856ca4dfbbd..5839f4d447d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,7 +10,7 @@ ### Fixes - Android: Count deep sleep in breadcrumb, screenshot and view hierarchy debounce windows, so the first low-memory or battery breadcrumb after a long Doze is no longer dropped ([#6590](https://github.com/getsentry/sentry-java/pull/6590)) -- Android: End `ui.load` transactions at their deadline as `deadline_exceeded` when the device slept or the app was frozen, instead of reporting TTID, TTFD and app start values that are hours long ([#6599](https://github.com/getsentry/sentry-java/pull/6599)) +- Android: Mark transactions and spans that finish after their deadline as `deadline_exceeded`, so `ui.load` transactions with TTID, TTFD or app start values that are hours long after a device sleep no longer report `ok` ([#6599](https://github.com/getsentry/sentry-java/pull/6599)) ## 8.64.0