fix: TTID/TTFD for app start transactions

The TTFD/TTID spans and measurements for app start transactions were
wrong, as they didn't include the app start duration. This is fixed now.

Fixes GH-3471

CHANGELOG.md

@@ -10,6 +10,7 @@
 ### Fixes
 
 - TTFD waits for next drawn frame (#3505)
+- Fix TTID/TTFD for app start transactions (#3512)
 
 ## 8.17.2
 

Sources/Sentry/SentryTimeToDisplayTracker.m

@@ -66,6 +66,18 @@ - (void)startForTracer:(SentryTracer *)tracer
 
     [SentryDependencyContainer.sharedInstance.framesTracker addListener:self];
     [tracer setFinishCallback:^(SentryTracer *_tracer) {
+        // If the start time of the tracer changes, which is the case for app start transactions, we
+        // also need to adapt the start time of our spans.
+        self.initialDisplaySpan.startTimestamp = _tracer.startTimestamp;
+        [self addTimeToDisplayMeasurement:self.initialDisplaySpan name:@"time_to_initial_display"];
+
+        if (self.fullDisplaySpan == nil) {
+            return;
+        }
+
+        self.fullDisplaySpan.startTimestamp = _tracer.startTimestamp;
+        [self addTimeToDisplayMeasurement:self.fullDisplaySpan name:@"time_to_full_display"];
+
         if (self.fullDisplaySpan.status != kSentrySpanStatusDeadlineExceeded) {
             return;
         }
@@ -97,8 +109,6 @@ - (void)framesTrackerHasNewFrame
     if (_initialDisplayReported && self.initialDisplaySpan.isFinished == NO) {
         self.initialDisplaySpan.timestamp = finishTime;
 
-        [self addTimeToDisplayMeasurement:self.initialDisplaySpan name:@"time_to_initial_display"];
-
         [self.initialDisplaySpan finish];
 
         if (!_waitForFullDisplay) {
@@ -109,8 +119,6 @@ - (void)framesTrackerHasNewFrame
         && self.initialDisplaySpan.isFinished == YES) {
         self.fullDisplaySpan.timestamp = finishTime;
 
-        [self addTimeToDisplayMeasurement:self.fullDisplaySpan name:@"time_to_full_display"];
-
         [self.fullDisplaySpan finish];
     }
 

Sources/Sentry/SentryTracer.m

@@ -491,6 +491,12 @@ - (void)finishInternal
         }
         [super finishWithStatus:_finishStatus];
     }
+#if SENTRY_HAS_UIKIT
+    if (appStartMeasurement != nil) {
+        [self updateStartTime:appStartMeasurement.appStartTimestamp];
+    }
+#endif // SENTRY_HAS_UIKIT
+
     [self.delegate tracerDidFinish:self];
 
     if (self.finishCallback) {
@@ -501,12 +507,6 @@ - (void)finishInternal
         self.finishCallback = nil;
     }
 
-#if SENTRY_HAS_UIKIT
-    if (appStartMeasurement != nil) {
-        [self updateStartTime:appStartMeasurement.appStartTimestamp];
-    }
-#endif // SENTRY_HAS_UIKIT
-
     // Prewarming can execute code up to viewDidLoad of a UIViewController, and keep the app in the
     // background. This can lead to auto-generated transactions lasting for minutes or even hours.
     // Therefore, we drop transactions lasting longer than SENTRY_AUTO_TRANSACTION_MAX_DURATION.

Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift

@@ -28,7 +28,7 @@ class SentryTimeToDisplayTrackerTest: XCTestCase {
         func getTracer() throws -> SentryTracer {
             let options = Options()
             let hub = TestHub(client: SentryClient(options: options, fileManager: try TestFileManager(options: options), deleteOldEnvelopeItems: false), andScope: nil)
-            return SentryTracer(transactionContext: TransactionContext(operation: "Test Operation"), hub: hub, configuration: SentryTracerConfiguration(block: {
+            return SentryTracer(transactionContext: TransactionContext(operation: "ui.load"), hub: hub, configuration: SentryTracerConfiguration(block: {
                 $0.waitForChildren = true
                 $0.timerFactory = self.timerFactory
                 $0.dispatchQueueWrapper = TestSentryDispatchQueueWrapper()
@@ -67,6 +67,7 @@ class SentryTimeToDisplayTrackerTest: XCTestCase {
         expect(ttidSpan.isFinished) == false
 
         fixture.displayLinkWrapper.normalFrame()
+        tracer.finish()
 
         expect(ttidSpan.timestamp) == fixture.dateProvider.date()
         expect(ttidSpan.isFinished) == true
@@ -97,8 +98,7 @@ class SentryTimeToDisplayTrackerTest: XCTestCase {
 
         expect(ttidSpan?.isFinished) == true
         expect(ttidSpan?.timestamp) == Date(timeIntervalSince1970: 9)
-
-        assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 2_000)
+        expect(tracer.measurements["time_to_initial_display"]) == nil
 
         fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11))
         sut.reportFullyDisplayed()
@@ -188,6 +188,7 @@ class SentryTimeToDisplayTrackerTest: XCTestCase {
 
         fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 12))
         fixture.displayLinkWrapper.normalFrame()
+        tracer.finish()
 
         expect(sut.initialDisplaySpan?.isFinished) == true
         expect(sut.initialDisplaySpan?.timestamp) == Date(timeIntervalSince1970: 12)
@@ -284,6 +285,74 @@ class SentryTimeToDisplayTrackerTest: XCTestCase {
         expect(sut.fullDisplaySpan) == nil
         expect(tracer.measurements["time_to_full_display"]) == nil
     }
+
+    func testTracerWithAppStartData_notWaitingForFullDisplay() throws {
+        let appStartMeasurement = TestData.getAppStartMeasurement(type: .cold, appStartTimestamp: Date(timeIntervalSince1970: 6))
+        SentrySDK.setAppStartMeasurement(appStartMeasurement)
+
+        fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 7))
+
+        let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: false)
+        let tracer = try fixture.getTracer()
+
+        sut.start(for: tracer)
+
+        fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 8))
+        sut.reportInitialDisplay()
+        fixture.displayLinkWrapper.normalFrame()
+
+        fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9))
+        sut.reportFullyDisplayed()
+        fixture.displayLinkWrapper.normalFrame()
+
+        tracer.finish()
+
+        let ttidSpan = sut.initialDisplaySpan
+        expect(ttidSpan?.isFinished) == true
+        expect(ttidSpan?.startTimestamp) == tracer.startTimestamp
+        expect(ttidSpan?.timestamp) == Date(timeIntervalSince1970: 8)
+        assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 2_000)
+
+        expect(sut.fullDisplaySpan) == nil
+        expect(tracer.measurements["time_to_full_display"]) == nil
+
+        expect(Dynamic(self.fixture.framesTracker).listeners.count) == 0
+    }
+
+    func testTracerWithAppStartData_waitingForFullDisplay() throws {
+        let appStartMeasurement = TestData.getAppStartMeasurement(type: .cold, appStartTimestamp: Date(timeIntervalSince1970: 6))
+        SentrySDK.setAppStartMeasurement(appStartMeasurement)
+
+        fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 7))
+
+        let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true)
+        let tracer = try fixture.getTracer()
+
+        sut.start(for: tracer)
+
+        fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 8))
+        sut.reportInitialDisplay()
+        fixture.displayLinkWrapper.normalFrame()
+
+        fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9))
+        sut.reportFullyDisplayed()
+        fixture.displayLinkWrapper.normalFrame()
+
+        tracer.finish()
+
+        let ttidSpan = sut.initialDisplaySpan
+
+        expect(ttidSpan?.isFinished) == true
+        expect(ttidSpan?.startTimestamp) == tracer.startTimestamp
+        expect(ttidSpan?.timestamp) == Date(timeIntervalSince1970: 8)
+        assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 2_000)
+
+        expect(sut.fullDisplaySpan?.startTimestamp) == ttidSpan?.startTimestamp
+        expect(sut.fullDisplaySpan?.timestamp) == Date(timeIntervalSince1970: 9)
+        assertMeasurement(tracer: tracer, name: "time_to_full_display", duration: 3_000)
+
+        expect(Dynamic(self.fixture.framesTracker).listeners.count) == 0
+    }
 
     func assertMeasurement(tracer: SentryTracer, name: String, duration: TimeInterval) {
         expect(tracer.measurements[name]?.value) == NSNumber(value: duration)