diff --git a/CHANGELOG.md b/CHANGELOG.md index 3b36713778..1f58c59590 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,7 @@ - UIViewController with Xcode 16 in debug (#4523). The Xcode 16 build setting [ENABLE_DEBUG_DYLIB](https://developer.apple.com/documentation/xcode/build-settings-reference#Enable-Debug-Dylib-Support), which is turned on by default only in debug, could lead to missing UIViewController traces. - Concurrency crash with Swift 6 (#4512) - Make `Scope.span` fully thread safe (#4519) +- - Finish TTFD when not calling reportFullyDisplayed before binding a new transaction to the scope (#4526). ## 8.40.1 diff --git a/Sources/Sentry/SentryPerformanceTracker.m b/Sources/Sentry/SentryPerformanceTracker.m index 322e23d9ce..6e7d862e5f 100644 --- a/Sources/Sentry/SentryPerformanceTracker.m +++ b/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 diff --git a/Sources/Sentry/SentryTimeToDisplayTracker.m b/Sources/Sentry/SentryTimeToDisplayTracker.m index 44bdb73b53..242ad76db5 100644 --- a/Sources/Sentry/SentryTimeToDisplayTracker.m +++ b/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 diff --git a/Sources/Sentry/SentryUIViewControllerPerformanceTracker.m b/Sources/Sentry/SentryUIViewControllerPerformanceTracker.m index c7d051e15b..513f2a6653 100644 --- a/Sources/Sentry/SentryUIViewControllerPerformanceTracker.m +++ b/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,15 +100,14 @@ - (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); @@ -117,13 +115,22 @@ - (void)createTransaction:(UIViewController *)controller // 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; diff --git a/Sources/Sentry/include/SentryTimeToDisplayTracker.h b/Sources/Sentry/include/SentryTimeToDisplayTracker.h index f8406a5205..06a3a25a1f 100644 --- a/Sources/Sentry/include/SentryTimeToDisplayTracker.h +++ b/Sources/Sentry/include/SentryTimeToDisplayTracker.h @@ -35,6 +35,8 @@ SENTRY_NO_INIT - (void)reportFullyDisplayed; +- (void)finishSpansIfNotFinished; + @end NS_ASSUME_NONNULL_END diff --git a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift index 4c3db6b012..077bf7479f 100644 --- a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift +++ b/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)) diff --git a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryUIViewControllerPerformanceTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryUIViewControllerPerformanceTrackerTests.swift index 5408af4e39..0358748c69 100644 --- a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryUIViewControllerPerformanceTrackerTests.swift +++ b/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()