Merge branch 'main' into fix/opacity-animation-masking

CHANGELOG.md

@@ -13,6 +13,7 @@
 - Concurrency crash with Swift 6 (#4512)
 - Make `Scope.span` fully thread safe (#4519)
 - Session replay opacity animation masking (#4532)
+- Finish TTFD when not calling reportFullyDisplayed before binding a new transaction to the scope (#4526).
 
 ## 8.40.1
 

Sources/Sentry/SentryPerformanceTracker.m

@@ -78,7 +78,8 @@ - (SentrySpanId *)startSpanWithName:(NSString *)name
         }
 #endif // SENTRY_HAS_UIKIT
 
-        SENTRY_LOG_DEBUG(@"Creating new transaction bound to scope: %d", bindToScope);
+        SENTRY_LOG_DEBUG(
+            @"Starting new transaction for %@ with bindToScope: %d", name, bindToScope);
 
         newSpan = [SentrySDK.currentHub
             startTransactionWithContext:context

Sources/Sentry/SentryTimeToDisplayTracker.m

@@ -137,6 +137,21 @@ - (void)reportFullyDisplayed
     [_dispatchQueueWrapper dispatchAsyncOnMainQueue:^{ self->_fullyDisplayedReported = YES; }];
 }
 
+- (void)finishSpansIfNotFinished
+{
+    if (self.initialDisplaySpan.isFinished == NO) {
+        [self.initialDisplaySpan finish];
+    }
+
+    if (self.fullDisplaySpan.isFinished == NO) {
+        SENTRY_LOG_WARN(@"You didn't call SentrySDK.reportFullyDisplayed() for UIViewController: "
+                        @"%@. Finishing full display span with status: %@.",
+            _controllerName, nameForSentrySpanStatus(kSentrySpanStatusDeadlineExceeded));
+
+        [self.fullDisplaySpan finishWithStatus:kSentrySpanStatusDeadlineExceeded];
+    }
+}
+
 - (void)framesTrackerHasNewFrame:(NSDate *)newFrameDate
 {
     // The purpose of TTID and TTFD is to measure how long

Sources/Sentry/SentryUIViewControllerPerformanceTracker.m

@@ -85,8 +85,7 @@ - (void)viewControllerLoadView:(UIViewController *)controller
         callbackToOrigin:callbackToOrigin
                    block:^{
                        SENTRY_LOG_DEBUG(@"Tracking loadView");
-                       [self createTransaction:controller];
-                       [self createTimeToDisplay:controller];
+                       [self startRootSpanFor:controller];
                        [self measurePerformance:@"loadView"
                                          target:controller
                                callbackToOrigin:callbackToOrigin];
@@ -101,29 +100,37 @@ - (void)viewControllerViewDidLoad:(UIViewController *)controller
         callbackToOrigin:callbackToOrigin
                    block:^{
                        SENTRY_LOG_DEBUG(@"Tracking viewDidLoad");
-                       [self createTransaction:controller];
-                       [self createTimeToDisplay:controller];
+                       [self startRootSpanFor:controller];
                        [self measurePerformance:@"viewDidLoad"
                                          target:controller
                                callbackToOrigin:callbackToOrigin];
                    }];
 }
 
-- (void)createTransaction:(UIViewController *)controller
+- (void)startRootSpanFor:(UIViewController *)controller
 {
     SentrySpanId *spanId
         = objc_getAssociatedObject(controller, &SENTRY_UI_PERFORMANCE_TRACKER_SPAN_ID);
 
     // If the user manually calls loadView outside the lifecycle we don't start a new transaction
     // and override the previous id stored.
     if (spanId == nil) {
+
+        // The tracker must create a new transaction and bind it to the scope when there is no
+        // active span. If the user didn't call reportFullyDisplayed, the previous UIViewController
+        // transaction is still bound to the scope because it waits for its children to finish,
+        // including the TTFD span. Therefore, we need to finish the TTFD span so the tracer can
+        // finish and remove itself from the scope. We don't need to finish the transaction because
+        // we already finished it in viewControllerViewDidAppear.
+        if (self.tracker.activeSpanId == nil) {
+            [self.currentTTDTracker finishSpansIfNotFinished];
+        }
+
         NSString *name = [SwiftDescriptor getObjectClassName:controller];
         spanId = [self.tracker startSpanWithName:name
                                       nameSource:kSentryTransactionNameSourceComponent
                                        operation:SentrySpanOperationUILoad
                                           origin:SentryTraceOriginAutoUIViewController];
-        SENTRY_LOG_DEBUG(@"Started span with id %@ to track view controller %@.",
-            spanId.sentrySpanIdString, name);
 
         // Use the target itself to store the spanId to avoid using a global mapper.
         objc_setAssociatedObject(controller, &SENTRY_UI_PERFORMANCE_TRACKER_SPAN_ID, spanId,
@@ -133,13 +140,15 @@ - (void)createTransaction:(UIViewController *)controller
         // to serve as an umbrella transaction that will capture every span
         // happening while the transaction is active.
         if (self.tracker.activeSpanId == nil) {
+            SENTRY_LOG_DEBUG(@"Started new transaction with id %@ to track view controller %@.",
+                spanId.sentrySpanIdString, name);
             [self.tracker pushActiveSpan:spanId];
+        } else {
+            SENTRY_LOG_DEBUG(@"Started child span with id %@ to track view controller %@.",
+                spanId.sentrySpanIdString, name);
         }
     }
-}
 
-- (void)createTimeToDisplay:(UIViewController *)controller
-{
     SentrySpan *vcSpan = [self viewControllerPerformanceSpan:controller];
 
     if (![vcSpan isKindOfClass:[SentryTracer self]]) {
@@ -154,6 +163,8 @@ - (void)createTimeToDisplay:(UIViewController *)controller
         return;
     }
 
+    [self.currentTTDTracker finishSpansIfNotFinished];
+
     SentryTimeToDisplayTracker *ttdTracker =
         [[SentryTimeToDisplayTracker alloc] initForController:controller
                                            waitForFullDisplay:self.enableWaitForFullDisplay
@@ -162,7 +173,6 @@ - (void)createTimeToDisplay:(UIViewController *)controller
     if ([ttdTracker startForTracer:(SentryTracer *)vcSpan]) {
         objc_setAssociatedObject(controller, &SENTRY_UI_PERFORMANCE_TRACKER_TTD_TRACKER, ttdTracker,
             OBJC_ASSOCIATION_ASSIGN);
-
         self.currentTTDTracker = ttdTracker;
     } else {
         self.currentTTDTracker = nil;

Sources/Sentry/include/SentryTimeToDisplayTracker.h

@@ -35,6 +35,8 @@ SENTRY_NO_INIT
 
 - (void)reportFullyDisplayed;
 
+- (void)finishSpansIfNotFinished;
+
 @end
 
 NS_ASSUME_NONNULL_END

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

@@ -412,6 +412,77 @@ class SentryTimeToDisplayTrackerTest: XCTestCase {
 
         XCTAssertEqual(Dynamic(self.fixture.framesTracker).listeners.count, 0)
     }
+
+    func testFinish_WithoutCallingReportFullyDisplayed() throws {
+        fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9))
+
+        let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true)
+        let tracer = try fixture.getTracer()
+
+        sut.start(for: tracer)
+
+        fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 10))
+        sut.reportInitialDisplay()
+        fixture.displayLinkWrapper.normalFrame()
+
+        fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11))
+        sut.finishSpansIfNotFinished()
+
+        fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 12))
+        fixture.displayLinkWrapper.normalFrame()
+
+        fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 13))
+        tracer.finish()
+
+        XCTAssertNotNil(sut.fullDisplaySpan)
+        XCTAssertEqual(sut.fullDisplaySpan?.startTimestamp, Date(timeIntervalSince1970: 9))
+        XCTAssertEqual(sut.fullDisplaySpan?.timestamp, Date(timeIntervalSince1970: 10))
+        XCTAssertEqual(sut.fullDisplaySpan?.status, .deadlineExceeded)
+
+        XCTAssertEqual(sut.fullDisplaySpan?.spanDescription, "UIViewController full display - Deadline Exceeded")
+        XCTAssertEqual(sut.fullDisplaySpan?.operation, SentrySpanOperationUILoadFullDisplay)
+        XCTAssertEqual(sut.fullDisplaySpan?.origin, "manual.ui.time_to_display")
+
+        assertMeasurement(tracer: tracer, name: "time_to_full_display", duration: 1_000)
+
+        XCTAssertEqual(Dynamic(self.fixture.framesTracker).listeners.count, 0)
+    }
+
+    func testFinish_WithoutTTID() throws {
+        fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9))
+
+        let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true)
+        let tracer = try fixture.getTracer()
+
+        sut.start(for: tracer)
+
+        tracer.finish()
+
+        fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 10))
+
+        sut.finishSpansIfNotFinished()
+
+        fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11))
+
+        let ttidSpan = try XCTUnwrap(sut.initialDisplaySpan)
+
+        XCTAssertEqual(ttidSpan.isFinished, true)
+        XCTAssertEqual(ttidSpan.startTimestamp, tracer.startTimestamp)
+        XCTAssertEqual(ttidSpan.timestamp, Date(timeIntervalSince1970: 10))
+        assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 1_000)
+
+        let fullDisplaySpan = try XCTUnwrap(sut.fullDisplaySpan)
+        XCTAssertEqual(fullDisplaySpan.startTimestamp, tracer.startTimestamp)
+        XCTAssertEqual(fullDisplaySpan.timestamp, ttidSpan.timestamp)
+        XCTAssertEqual(fullDisplaySpan.status, .deadlineExceeded)
+
+        XCTAssertEqual(fullDisplaySpan.spanDescription, "UIViewController full display - Deadline Exceeded")
+        XCTAssertEqual(fullDisplaySpan.operation, SentrySpanOperationUILoadFullDisplay)
+        XCTAssertEqual(fullDisplaySpan.origin, "manual.ui.time_to_display")
+        assertMeasurement(tracer: tracer, name: "time_to_full_display", duration: 1_000)
+
+        XCTAssertEqual(Dynamic(self.fixture.framesTracker).listeners.count, 0)
+    }
 
     func assertMeasurement(tracer: SentryTracer, name: String, duration: TimeInterval) {
         XCTAssertEqual(tracer.measurements[name]?.value, NSNumber(value: duration))

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

@@ -766,6 +766,129 @@ class SentryUIViewControllerPerformanceTrackerTests: XCTestCase {
         XCTAssertEqual("ui.load", child3.operation)
         XCTAssertEqual("viewDidLoad", child3.spanDescription)
     }
+
+    func test_waitForFullDisplay_NewViewControllerLoaded_BeforeReportTTFD() throws {
+        let sut = fixture.getSut()
+        let tracker = fixture.tracker
+        let firstController = TestViewController()
+        let secondController = TestViewController()
+
+        var firstTracer: SentryTracer?
+        var secondTracer: SentryTracer?
+
+        sut.enableWaitForFullDisplay = true
+
+        let expectedFirstTTFDStartTimestamp = fixture.dateProvider.date()
+
+        sut.viewControllerLoadView(firstController) {
+            firstTracer = self.getStack(tracker).first as? SentryTracer
+        }
+        advanceTime(bySeconds: 1)
+        sut.viewControllerViewDidLoad(firstController) { /* Empty on purpose */ }
+        sut.viewControllerViewWillAppear(firstController) { /* Empty on purpose */ }
+        sut.viewControllerViewDidAppear(firstController) { /* Empty on purpose */ }
+
+        let firstFullDisplaySpan = try XCTUnwrap(firstTracer?.children.first { $0.operation == "ui.load.full_display" })
+
+        XCTAssertFalse(firstFullDisplaySpan.isFinished)
+        XCTAssertEqual(expectedFirstTTFDStartTimestamp, firstFullDisplaySpan.startTimestamp)
+        XCTAssertEqual(firstTracer?.traceId, SentrySDK.span?.traceId)
+
+        advanceTime(bySeconds: 1)
+        let expectedFirstTTFDTimestamp = fixture.dateProvider.date()
+
+        sut.viewControllerLoadView(secondController) {
+            secondTracer = self.getStack(tracker).first as? SentryTracer
+        }
+
+        XCTAssertTrue(firstFullDisplaySpan.isFinished)
+        XCTAssertEqual(expectedFirstTTFDTimestamp, firstFullDisplaySpan.timestamp)
+        XCTAssertEqual(.deadlineExceeded, firstFullDisplaySpan.status)
+
+        XCTAssertEqual(secondTracer?.traceId, SentrySDK.span?.traceId)
+
+        let secondFullDisplaySpan = try XCTUnwrap(secondTracer?.children.first { $0.operation == "ui.load.full_display" }, "Did not find full display span for second UIViewController.")
+
+        XCTAssertFalse(secondFullDisplaySpan.isFinished)
+        XCTAssertEqual(expectedFirstTTFDTimestamp, secondFullDisplaySpan.startTimestamp)
+        XCTAssertEqual(secondTracer?.traceId, SentrySDK.span?.traceId)
+    }
+
+    func test_waitForFullDisplay_NewViewControllerLoaded_BeforeReportTTFD_FramesTrackerStopped() throws {
+        let sut = fixture.getSut()
+        let tracker = fixture.tracker
+        let firstController = TestViewController()
+        let secondController = TestViewController()
+
+        var firstTracer: SentryTracer?
+        var secondTracer: SentryTracer?
+
+        sut.enableWaitForFullDisplay = true
+
+        sut.viewControllerLoadView(firstController) {
+            firstTracer = self.getStack(tracker).first as? SentryTracer
+        }
+        sut.viewControllerViewDidLoad(firstController) { /* Empty on purpose */ }
+        sut.viewControllerViewWillAppear(firstController) { /* Empty on purpose */ }
+        sut.viewControllerViewDidAppear(firstController) { /* Empty on purpose */ }
+
+        let firstFullDisplaySpan = try XCTUnwrap(firstTracer?.children.first { $0.operation == "ui.load.full_display" })
+
+        XCTAssertFalse(firstFullDisplaySpan.isFinished)
+
+        fixture.framesTracker.stop()
+
+        advanceTime(bySeconds: 1)
+        let expectedFirstTTFDTimestamp = fixture.dateProvider.date()
+
+        sut.viewControllerLoadView(secondController) {
+            secondTracer = self.getStack(tracker).first as? SentryTracer
+        }
+
+        XCTAssertEqual(secondTracer?.traceId, SentrySDK.span?.traceId)
+        XCTAssertTrue(firstTracer?.isFinished ?? false)
+        XCTAssertTrue(firstFullDisplaySpan.isFinished)
+        XCTAssertEqual(expectedFirstTTFDTimestamp, firstFullDisplaySpan.timestamp)
+        XCTAssertEqual(.deadlineExceeded, firstFullDisplaySpan.status)
+
+        XCTAssertEqual(0, secondTracer?.children.filter { $0.operation == "ui.load.full_display" }.count, "There should be no full display span, because the frames tracker is not running.")
+    }
+
+    func test_waitForFullDisplay_NestedUIViewControllers_DoesNotFinishTTFDSpan() throws {
+        let sut = fixture.getSut()
+        let tracker = fixture.tracker
+        let firstController = TestViewController()
+        let secondController = TestViewController()
+
+        var firstTracer: SentryTracer?
+        var secondTracer: SentryTracer?
+
+        sut.enableWaitForFullDisplay = true
+
+        let expectedFirstTTFDStartTimestamp = fixture.dateProvider.date()
+        sut.viewControllerLoadView(firstController) {
+            firstTracer = self.getStack(tracker).first as? SentryTracer
+        }
+        sut.viewControllerViewDidLoad(firstController) { /* Empty on purpose */ }
+        sut.viewControllerViewWillAppear(firstController) { /* Empty on purpose */ }
+        advanceTime(bySeconds: 1)
+
+        let firstFullDisplaySpan = try XCTUnwrap(firstTracer?.children.first { $0.operation == "ui.load.full_display" })
+
+        XCTAssertFalse(firstFullDisplaySpan.isFinished)
+
+        sut.viewControllerLoadView(secondController) {
+            secondTracer = self.getStack(tracker).first as? SentryTracer
+        }
+
+        XCTAssertEqual(firstTracer?.traceId, secondTracer?.traceId, "First and second tracer should have the same trace id as the second view controller is nested in the first one.")
+
+        XCTAssertEqual(firstTracer?.traceId.sentryIdString, SentrySDK.span?.traceId.sentryIdString)
+
+        XCTAssertFalse(firstTracer?.isFinished ?? true)
+        XCTAssertFalse(firstFullDisplaySpan.isFinished)
+        XCTAssertEqual(expectedFirstTTFDStartTimestamp, firstFullDisplaySpan.startTimestamp)
+    }
 
     func test_captureAllAutomaticSpans() {
         let sut = fixture.getSut()