Skip to content

Fix TTFD measurement when API called too early #4297

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 5 commits into from
Apr 15, 2025
Merged

Fix TTFD measurement when API called too early #4297

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
2c44f51
Sentry.reportFullyDisplayed now sets a flag if the ttid is not finished.
stefanosiano Mar 28, 2025
4d262fd
updated changelog
stefanosiano Mar 28, 2025
963adfa
updated comment
stefanosiano Apr 15, 2025
33feebd
Merge branch 'main' into fix/ttfd-measurement
stefanosiano Apr 15, 2025
f08a847
Update CHANGELOG.md
stefanosiano Apr 15, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions CHANGELOG.md
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,5 +1,11 @@
# Changelog

## Unreleased

### Fixes

- Fix TTFD measurement when API called too early ([#4297](https://github.com/getsentry/sentry-java/pull/4297))

## 8.8.0

### Features
Expand Down
84 changes: 57 additions & 27 deletions sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -91,6 +91,9 @@ public final class ActivityLifecycleIntegration

private final @NotNull ActivityFramesTracker activityFramesTracker;
private final @NotNull AutoClosableReentrantLock lock = new AutoClosableReentrantLock();
private boolean fullyDisplayedCalled = false;
private final @NotNull AutoClosableReentrantLock fullyDisplayedLock =
new AutoClosableReentrantLock();

public ActivityLifecycleIntegration(
final @NotNull Application application,
Expand Down Expand Up @@ -413,12 +416,17 @@ public void onActivityCreated(
scopes.configureScope(scope -> scope.setScreen(activityClassName));
}
startTracing(activity);
final @Nullable ISpan ttidSpan = ttidSpanMap.get(activity);
final @Nullable ISpan ttfdSpan = ttfdSpanMap.get(activity);

firstActivityCreated = true;

if (performanceEnabled && ttfdSpan != null && fullyDisplayedReporter != null) {
fullyDisplayedReporter.registerFullyDrawnListener(() -> onFullFrameDrawn(ttfdSpan));
if (performanceEnabled
&& ttidSpan != null
&& ttfdSpan != null
&& fullyDisplayedReporter != null) {
fullyDisplayedReporter.registerFullyDrawnListener(
() -> onFullFrameDrawn(ttidSpan, ttfdSpan));
}
}
}
Expand Down Expand Up @@ -635,37 +643,59 @@ private void onFirstFrameDrawn(final @Nullable ISpan ttfdSpan, final @Nullable I
}
finishAppStartSpan();

if (options != null && ttidSpan != null) {
final SentryDate endDate = options.getDateProvider().now();
final long durationNanos = endDate.diff(ttidSpan.getStartDate());
final long durationMillis = TimeUnit.NANOSECONDS.toMillis(durationNanos);
ttidSpan.setMeasurement(
MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY, durationMillis, MILLISECOND);

if (ttfdSpan != null && ttfdSpan.isFinished()) {
ttfdSpan.updateEndDate(endDate);
// If the ttfd span was finished before the first frame we adjust the measurement, too
// Sentry.reportFullyDisplayed can be run in any thread, so we have to ensure synchronization
// with first frame drawn
try (final @NotNull ISentryLifecycleToken ignored = fullyDisplayedLock.acquire()) {
if (options != null && ttidSpan != null) {
final SentryDate endDate = options.getDateProvider().now();
final long durationNanos = endDate.diff(ttidSpan.getStartDate());
final long durationMillis = TimeUnit.NANOSECONDS.toMillis(durationNanos);
ttidSpan.setMeasurement(
MeasurementValue.KEY_TIME_TO_FULL_DISPLAY, durationMillis, MILLISECOND);
MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY, durationMillis, MILLISECOND);
// If Sentry.reportFullyDisplayed was called before the first frame is drawn, we finish
// the ttfd now
if (ttfdSpan != null && fullyDisplayedCalled) {
fullyDisplayedCalled = false;
ttidSpan.setMeasurement(
MeasurementValue.KEY_TIME_TO_FULL_DISPLAY, durationMillis, MILLISECOND);
ttfdSpan.setMeasurement(
MeasurementValue.KEY_TIME_TO_FULL_DISPLAY, durationMillis, MILLISECOND);
finishSpan(ttfdSpan, endDate);
}

finishSpan(ttidSpan, endDate);
} else {
finishSpan(ttidSpan);
if (fullyDisplayedCalled) {
finishSpan(ttfdSpan);
}
}
finishSpan(ttidSpan, endDate);
} else {
finishSpan(ttidSpan);
}
}

private void onFullFrameDrawn(final @Nullable ISpan ttfdSpan) {
if (options != null && ttfdSpan != null) {
final SentryDate endDate = options.getDateProvider().now();
final long durationNanos = endDate.diff(ttfdSpan.getStartDate());
final long durationMillis = TimeUnit.NANOSECONDS.toMillis(durationNanos);
ttfdSpan.setMeasurement(
MeasurementValue.KEY_TIME_TO_FULL_DISPLAY, durationMillis, MILLISECOND);
finishSpan(ttfdSpan, endDate);
} else {
finishSpan(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
try (final @NotNull ISentryLifecycleToken ignored = fullyDisplayedLock.acquire()) {
// If the TTID span didn't finish, it means the first frame was not drawn yet, which means
// Sentry.reportFullyDisplayed was called too early. We set a flag, so that whenever the TTID
// will finish, we will finish the TTFD span as well.
if (!ttidSpan.isFinished()) {
fullyDisplayedCalled = true;
return;
}
if (options != null) {
final SentryDate endDate = options.getDateProvider().now();
final long durationNanos = endDate.diff(ttfdSpan.getStartDate());
final long durationMillis = TimeUnit.NANOSECONDS.toMillis(durationNanos);
ttfdSpan.setMeasurement(
MeasurementValue.KEY_TIME_TO_FULL_DISPLAY, durationMillis, MILLISECOND);
finishSpan(ttfdSpan, endDate);
} else {
finishSpan(ttfdSpan);
}
}
}

private void finishExceededTtfdSpan(
Expand Down
72 changes: 55 additions & 17 deletions sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -54,6 +54,7 @@ import org.robolectric.shadow.api.Shadow
import org.robolectric.shadows.ShadowActivityManager
import java.util.Date
import java.util.concurrent.Future
import java.util.concurrent.TimeUnit
import kotlin.test.AfterTest
import kotlin.test.BeforeTest
import kotlin.test.Test
Expand Down Expand Up @@ -300,7 +301,7 @@ class ActivityLifecycleIntegrationTest {
val sut = fixture.getSut(initializer = {
it.tracesSampleRate = 1.0
it.isEnableTimeToFullDisplayTracing = true
it.idleTimeout = 200
it.idleTimeout = 100
})
sut.register(fixture.scopes, fixture.options)
sut.onActivityCreated(activity, fixture.bundle)
Expand All @@ -318,7 +319,7 @@ class ActivityLifecycleIntegrationTest {
)

// but when idle timeout has passed
Thread.sleep(400)
Thread.sleep(200)

// then the transaction should be finished
verify(fixture.scopes).captureTransaction(
Expand Down Expand Up @@ -815,7 +816,6 @@ class ActivityLifecycleIntegrationTest {

// when activity is resumed
sut.onActivityResumed(activity)
Thread.sleep(1)
runFirstDraw(view)
// end-time should be set
assertTrue(AppStartMetrics.getInstance().sdkInitTimeSpan.hasStopped())
Expand Down Expand Up @@ -863,17 +863,14 @@ class ActivityLifecycleIntegrationTest {
sut.onActivityCreated(activity, fixture.bundle)
sut.onActivityStarted(activity)
sut.onActivityResumed(activity)
Thread.sleep(1)
runFirstDraw(view)

val firstAppStartEndTime = AppStartMetrics.getInstance().sdkInitTimeSpan.projectedStopTimestamp

Thread.sleep(1)
sut.onActivityPaused(activity)
sut.onActivityStopped(activity)
sut.onActivityStarted(activity)
sut.onActivityResumed(activity)
Thread.sleep(1)
runFirstDraw(view)

// then the end time should not be overwritten
Expand Down Expand Up @@ -983,6 +980,36 @@ class ActivityLifecycleIntegrationTest {
)
}

@Test
fun `When isEnableTimeToFullDisplayTracing is true and reportFullyDrawn is called, ttfd is finished on first frame if ttid is running`() {
val sut = fixture.getSut()
val view = fixture.createView()
val activity = mock<Activity>()
whenever(activity.findViewById<View>(any())).thenReturn(view)
fixture.options.tracesSampleRate = 1.0
fixture.options.isEnableTimeToFullDisplayTracing = true
sut.register(fixture.scopes, fixture.options)
sut.onActivityCreated(activity, fixture.bundle)
sut.onActivityResumed(activity)
val ttidSpan = sut.ttidSpanMap[activity]
val ttfdSpan = sut.ttfdSpanMap[activity]

// Assert the ttfd span is running and a timeout autoCancel future has been scheduled
assertNotNull(ttidSpan)
assertNotNull(ttfdSpan)
assertFalse(ttidSpan.isFinished)
assertFalse(ttfdSpan.isFinished)

// ReportFullyDrawn should not finish the ttfd span, as the ttid is still running
fixture.options.fullyDisplayedReporter.reportFullyDrawn()
assertFalse(ttfdSpan.isFinished)

// But when ReportFullyDrawn should not finish the ttfd span, as the ttid is still running
runFirstDraw(view)
assertTrue(ttidSpan.isFinished)
assertTrue(ttfdSpan.isFinished)
}

@Test
fun `When isEnableTimeToFullDisplayTracing is true and reportFullyDrawn is called, ttfd autoClose future is cancelled`() {
val sut = fixture.getSut()
Expand All @@ -991,16 +1018,17 @@ class ActivityLifecycleIntegrationTest {
sut.register(fixture.scopes, fixture.options)
val activity = mock<Activity>()
sut.onActivityCreated(activity, fixture.bundle)
val ttidSpan = sut.ttidSpanMap[activity]
val ttfdSpan = sut.ttfdSpanMap[activity]
var autoCloseFuture = sut.getProperty<Future<*>?>("ttfdAutoCloseFuture")
ttidSpan?.finish()

// Assert the ttfd span is running and a timeout autoCancel future has been scheduled
assertNotNull(ttfdSpan)
assertFalse(ttfdSpan.isFinished)
assertNotNull(autoCloseFuture)

// ReportFullyDrawn should finish the ttfd span and cancel the future
Thread.sleep(1)
fixture.options.fullyDisplayedReporter.reportFullyDrawn()
assertTrue(ttfdSpan.isFinished)
assertNotEquals(SpanStatus.DEADLINE_EXCEEDED, ttfdSpan.status)
Expand Down Expand Up @@ -1077,7 +1105,6 @@ class ActivityLifecycleIntegrationTest {
assertFalse(ttidSpan.isFinished)

// Mock the draw of the view. The ttid span should finish now
Thread.sleep(1)
runFirstDraw(view)
assertTrue(ttidSpan.isFinished)

Expand All @@ -1097,7 +1124,9 @@ class ActivityLifecycleIntegrationTest {

@Test
fun `When isEnableTimeToFullDisplayTracing is true and reportFullyDrawn is called too early, ttfd is adjusted to equal ttid`() {
val sut = fixture.getSut()
val sut = fixture.getSut() {
// it.fullyDisplayedReporter = mock()
}
val view = fixture.createView()
val activity = mock<Activity>()
fixture.options.tracesSampleRate = 1.0
Expand All @@ -1116,18 +1145,28 @@ class ActivityLifecycleIntegrationTest {
assertFalse(ttfdSpan.isFinished)

// Let's finish the ttfd span too early (before the first view is drawn)
ttfdSpan.finish()
assertTrue(ttfdSpan.isFinished)
val oldEndDate = ttfdSpan.finishDate
fixture.options.fullyDisplayedReporter.reportFullyDrawn()

// Mock the draw of the view. The ttid span should finish now and the ttfd end date should be adjusted
// The TTFD shouldn't be finished yet
assertFalse(ttfdSpan.isFinished)

// Mock the draw of the view. The ttid span should finish now and the ttfd, too
runFirstDraw(view)
assertTrue(ttidSpan.isFinished)
val newEndDate = ttfdSpan.finishDate
assertNotEquals(newEndDate, oldEndDate)
assertEquals(newEndDate, ttidSpan.finishDate)
assertTrue(ttfdSpan.isFinished)
assertEquals(ttfdSpan.finishDate, ttidSpan.finishDate)

sut.onActivityDestroyed(activity)

// The measurements should be set to the same value for ttid and ttfd
val ttidDuration = TimeUnit.NANOSECONDS.toMillis(ttidSpan.finishDate!!.diff(ttidSpan.startDate))
val ttfdDuration = TimeUnit.NANOSECONDS.toMillis(ttfdSpan.finishDate!!.diff(ttfdSpan.startDate))
assertEquals(ttidDuration, ttfdDuration)
// TTID also has initial display measurement, but TTFD has not
assertEquals(ttidDuration, ttidSpan.measurements[MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY]!!.value)
assertEquals(ttidDuration, ttidSpan.measurements[MeasurementValue.KEY_TIME_TO_FULL_DISPLAY]!!.value)
assertEquals(ttidDuration, ttfdSpan.measurements[MeasurementValue.KEY_TIME_TO_FULL_DISPLAY]!!.value)

verify(fixture.scopes).captureTransaction(
check {
// ttid and ttfd measurements should be the same
Expand Down Expand Up @@ -1189,7 +1228,6 @@ class ActivityLifecycleIntegrationTest {
assertFalse(ttfdSpan.isFinished)

// Run the autoClose task 1 ms after finishing the ttid span and assert the ttfd span is finished
Thread.sleep(1)
deferredExecutorService.runAll()
assertTrue(ttfdSpan.isFinished)

Expand Down
Loading