From 91a603d71f3cd50b887a48bf420233471f3b434b Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 19 Dec 2023 09:59:15 +0100 Subject: [PATCH 1/2] remove performanceV2 option and other fixes --- CHANGELOG.md | 5 + .../LoremIpsumViewController.swift | 5 +- Sources/Sentry/SentryTimeToDisplayTracker.m | 63 ++-- ...SentryUIViewControllerPerformanceTracker.m | 2 +- .../include/SentryTimeToDisplayTracker.h | 2 +- ...yPerformanceTrackingIntegrationTests.swift | 1 + .../SentryTimeToDisplayTrackerTest.swift | 287 +++++++++--------- ...iewControllerPerformanceTrackerTests.swift | 17 +- 8 files changed, 205 insertions(+), 177 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 7d813359883..97ca7afac61 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,11 @@ - Add frames delay to transactions (#3487) - Add slow and frozen frames to spans (#3450, #3478) + +### Fixes + +- TTFD waits for next drawn frame (#3505) + ## 8.17.2 ### Fixes diff --git a/Samples/iOS-Swift/iOS-Swift/ViewControllers/LoremIpsumViewController.swift b/Samples/iOS-Swift/iOS-Swift/ViewControllers/LoremIpsumViewController.swift index b3a113e37ff..d74750bd347 100644 --- a/Samples/iOS-Swift/iOS-Swift/ViewControllers/LoremIpsumViewController.swift +++ b/Samples/iOS-Swift/iOS-Swift/ViewControllers/LoremIpsumViewController.swift @@ -14,7 +14,10 @@ class LoremIpsumViewController: UIViewController { if let contents = FileManager.default.contents(atPath: path) { DispatchQueue.main.async { self.textView.text = String(data: contents, encoding: .utf8) - SentrySDK.reportFullyDisplayed() + + dispatchQueue.asyncAfter(deadline: .now() + 0.1) { + SentrySDK.reportFullyDisplayed() + } } } } diff --git a/Sources/Sentry/SentryTimeToDisplayTracker.m b/Sources/Sentry/SentryTimeToDisplayTracker.m index 99492abe4a1..1bf922378e6 100644 --- a/Sources/Sentry/SentryTimeToDisplayTracker.m +++ b/Sources/Sentry/SentryTimeToDisplayTracker.m @@ -26,7 +26,7 @@ @implementation SentryTimeToDisplayTracker { BOOL _waitForFullDisplay; - BOOL _isReadyToDisplay; + BOOL _initialDisplayReported; BOOL _fullyDisplayedReported; NSString *_controllerName; } @@ -37,8 +37,7 @@ - (instancetype)initForController:(UIViewController *)controller if (self = [super init]) { _controllerName = [SwiftDescriptor getObjectClassName:controller]; _waitForFullDisplay = waitForFullDisplay; - - _isReadyToDisplay = NO; + _initialDisplayReported = NO; _fullyDisplayedReported = NO; } return self; @@ -66,33 +65,26 @@ - (void)startForTracer:(SentryTracer *)tracer self.initialDisplaySpan.startTimestamp = tracer.startTimestamp; [SentryDependencyContainer.sharedInstance.framesTracker addListener:self]; - [tracer setFinishCallback:^( - SentryTracer *_tracer) { [self trimTTFDIdNecessaryForTracer:_tracer]; }]; + [tracer setFinishCallback:^(SentryTracer *_tracer) { + if (self.fullDisplaySpan.status != kSentrySpanStatusDeadlineExceeded) { + return; + } + + self.fullDisplaySpan.timestamp = self.initialDisplaySpan.timestamp; + self.fullDisplaySpan.spanDescription = [NSString + stringWithFormat:@"%@ - Deadline Exceeded", self.fullDisplaySpan.spanDescription]; + [self addTimeToDisplayMeasurement:self.fullDisplaySpan name:@"time_to_full_display"]; + }]; } -- (void)reportReadyToDisplay +- (void)reportInitialDisplay { - _isReadyToDisplay = YES; + _initialDisplayReported = YES; } - (void)reportFullyDisplayed { _fullyDisplayedReported = YES; - if (self.waitForFullDisplay && _isReadyToDisplay) { - // We need the timestamp to be able to calculate the duration - // but we can't finish first and add measure later because - // finishing the span may trigger the tracer finishInternal. - self.fullDisplaySpan.timestamp = - [SentryDependencyContainer.sharedInstance.dateProvider date]; - [self addTimeToDisplayMeasurement:self.fullDisplaySpan name:@"time_to_full_display"]; - [self.fullDisplaySpan finish]; - } -} - -- (void)addTimeToDisplayMeasurement:(SentrySpan *)span name:(NSString *)name -{ - NSTimeInterval duration = [span.timestamp timeIntervalSinceDate:span.startTimestamp] * 1000; - [span setMeasurement:name value:@(duration) unit:SentryMeasurementUnitDuration.millisecond]; } - (void)framesTrackerHasNewFrame @@ -102,32 +94,35 @@ - (void)framesTrackerHasNewFrame // The purpose of TTID and TTFD is to measure how long // takes to the content of the screen to change. // Thats why we need to wait for the next frame to be drawn. - if (_isReadyToDisplay && self.initialDisplaySpan.isFinished == NO) { + if (_initialDisplayReported && self.initialDisplaySpan.isFinished == NO) { self.initialDisplaySpan.timestamp = finishTime; [self addTimeToDisplayMeasurement:self.initialDisplaySpan name:@"time_to_initial_display"]; [self.initialDisplaySpan finish]; - [SentryDependencyContainer.sharedInstance.framesTracker removeListener:self]; + + if (!_waitForFullDisplay) { + [SentryDependencyContainer.sharedInstance.framesTracker removeListener:self]; + } } - if (_waitForFullDisplay && _fullyDisplayedReported && self.fullDisplaySpan.isFinished == NO) { + if (_waitForFullDisplay && _fullyDisplayedReported && self.fullDisplaySpan.isFinished == NO + && self.initialDisplaySpan.isFinished == YES) { self.fullDisplaySpan.timestamp = finishTime; - [self addTimeToDisplayMeasurement:self.initialDisplaySpan name:@"time_to_full_display"]; + [self addTimeToDisplayMeasurement:self.fullDisplaySpan name:@"time_to_full_display"]; [self.fullDisplaySpan finish]; } -} -- (void)trimTTFDIdNecessaryForTracer:(SentryTracer *)tracer -{ - if (self.fullDisplaySpan.status != kSentrySpanStatusDeadlineExceeded) { - return; + if (self.initialDisplaySpan.isFinished == YES && self.fullDisplaySpan.isFinished == YES) { + [SentryDependencyContainer.sharedInstance.framesTracker removeListener:self]; } +} - self.fullDisplaySpan.timestamp = self.initialDisplaySpan.timestamp; - self.fullDisplaySpan.spanDescription = - [NSString stringWithFormat:@"%@ - Deadline Exceeded", self.fullDisplaySpan.spanDescription]; +- (void)addTimeToDisplayMeasurement:(SentrySpan *)span name:(NSString *)name +{ + NSTimeInterval duration = [span.timestamp timeIntervalSinceDate:span.startTimestamp] * 1000; + [span setMeasurement:name value:@(duration) unit:SentryMeasurementUnitDuration.millisecond]; } @end diff --git a/Sources/Sentry/SentryUIViewControllerPerformanceTracker.m b/Sources/Sentry/SentryUIViewControllerPerformanceTracker.m index 922fdf4ac1c..4d3dd4c983e 100644 --- a/Sources/Sentry/SentryUIViewControllerPerformanceTracker.m +++ b/Sources/Sentry/SentryUIViewControllerPerformanceTracker.m @@ -182,7 +182,7 @@ - (void)viewControllerViewWillAppear:(UIViewController *)controller SentryTimeToDisplayTracker *ttdTracker = objc_getAssociatedObject(controller, &SENTRY_UI_PERFORMANCE_TRACKER_TTD_TRACKER); - [ttdTracker reportReadyToDisplay]; + [ttdTracker reportInitialDisplay]; }; [self limitOverride:@"viewWillAppear" diff --git a/Sources/Sentry/include/SentryTimeToDisplayTracker.h b/Sources/Sentry/include/SentryTimeToDisplayTracker.h index 1b239aa8f94..755179af4ec 100644 --- a/Sources/Sentry/include/SentryTimeToDisplayTracker.h +++ b/Sources/Sentry/include/SentryTimeToDisplayTracker.h @@ -29,7 +29,7 @@ SENTRY_NO_INIT - (void)startForTracer:(SentryTracer *)tracer; -- (void)reportReadyToDisplay; +- (void)reportInitialDisplay; - (void)reportFullyDisplayed; diff --git a/Tests/SentryTests/Integrations/Performance/SentryPerformanceTrackingIntegrationTests.swift b/Tests/SentryTests/Integrations/Performance/SentryPerformanceTrackingIntegrationTests.swift index 37376eabe95..de7f143d26b 100644 --- a/Tests/SentryTests/Integrations/Performance/SentryPerformanceTrackingIntegrationTests.swift +++ b/Tests/SentryTests/Integrations/Performance/SentryPerformanceTrackingIntegrationTests.swift @@ -1,3 +1,4 @@ +import Nimble import SentryTestUtils import XCTest diff --git a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift index f0bb2434c3f..c1e48bc0f7c 100644 --- a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift +++ b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift @@ -1,4 +1,5 @@ import Foundation +import Nimble import Sentry import SentryTestUtils import XCTest @@ -9,7 +10,7 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { private class Fixture { let dateProvider: TestCurrentDateProvider = TestCurrentDateProvider() - var tracer: SentryTracer { SentryTracer(transactionContext: TransactionContext(operation: "Test Operation"), hub: nil) } + let timerFactory = TestSentryNSTimerFactory() var displayLinkWrapper = TestDisplayLinkWrapper() var framesTracker: SentryFramesTracker @@ -23,6 +24,16 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { func getSut(for controller: UIViewController, waitForFullDisplay: Bool) -> SentryTimeToDisplayTracker { return SentryTimeToDisplayTracker(for: controller, waitForFullDisplay: waitForFullDisplay) } + + 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: { + $0.waitForChildren = true + $0.timerFactory = self.timerFactory + $0.dispatchQueueWrapper = TestSentryDispatchQueueWrapper() + })) + } } private lazy var fixture = Fixture() @@ -37,242 +48,246 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { clearTestState() } - func testReportInitialDisplay_notWaitingFullDisplay() throws { + func testReportInitialDisplay_notWaitingForFullDisplay() throws { let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: false) fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 7)) - let tracer = fixture.tracer + let tracer = try fixture.getTracer() sut.start(for: tracer) - XCTAssertEqual(tracer.children.count, 1) - XCTAssertEqual(Dynamic(fixture.framesTracker).listeners.count, 1) + expect(tracer.children.count) == 1 + expect(Dynamic(self.fixture.framesTracker).listeners.count) == 1 let ttidSpan = try XCTUnwrap(tracer.children.first, "Expected a TTID span") - XCTAssertEqual(ttidSpan.startTimestamp, fixture.dateProvider.date()) + expect(ttidSpan.startTimestamp) == fixture.dateProvider.date() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) - sut.reportReadyToDisplay() + sut.reportInitialDisplay() + expect(ttidSpan.timestamp) == nil + expect(ttidSpan.isFinished) == false + fixture.displayLinkWrapper.normalFrame() - XCTAssertEqual(ttidSpan.timestamp, fixture.dateProvider.date()) - XCTAssertTrue(ttidSpan.isFinished) - XCTAssertEqual(ttidSpan.spanDescription, "UIViewController initial display") - XCTAssertEqual(ttidSpan.operation, SentrySpanOperationUILoadInitialDisplay) - XCTAssertEqual(ttidSpan.origin, "auto.ui.time_to_display") + expect(ttidSpan.timestamp) == fixture.dateProvider.date() + expect(ttidSpan.isFinished) == true + expect(ttidSpan.spanDescription) == "UIViewController initial display" + expect(ttidSpan.operation) == SentrySpanOperationUILoadInitialDisplay + expect(ttidSpan.origin) == "auto.ui.time_to_display" assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 2_000) - XCTAssertEqual(Dynamic(fixture.framesTracker).listeners.count, 0) - } - - func testReportNewFrame_notReadyToDisplay() throws { - let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: false) - - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 7)) - - let tracer = fixture.tracer - - sut.start(for: tracer) - XCTAssertEqual(tracer.children.count, 1) - - let ttidSpan = try XCTUnwrap(tracer.children.first, "Expected a TTID span") - XCTAssertEqual(ttidSpan.startTimestamp, fixture.dateProvider.date()) - - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) - fixture.displayLinkWrapper.normalFrame() - - XCTAssertNil(ttidSpan.timestamp) - XCTAssertFalse(ttidSpan.isFinished) - - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 12)) - sut.reportReadyToDisplay() - fixture.displayLinkWrapper.normalFrame() - - XCTAssertEqual(ttidSpan.timestamp, fixture.dateProvider.date()) - XCTAssertTrue(ttidSpan.isFinished) + expect(Dynamic(self.fixture.framesTracker).listeners.count) == 0 } - func testreportInitialDisplay_waitForFullDisplay() { + func testReportInitialDisplay_waitForFullDisplay() throws { fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 7)) let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) - let tracer = fixture.tracer + let tracer = try fixture.getTracer() sut.start(for: tracer) - XCTAssertEqual(tracer.children.count, 2) + expect(tracer.children.count) == 2 - let ttidSpan = tracer.children.first - XCTAssertEqual(ttidSpan?.startTimestamp, fixture.dateProvider.date()) + let ttidSpan = sut.initialDisplaySpan + expect(ttidSpan?.startTimestamp) == fixture.dateProvider.date() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) - sut.reportReadyToDisplay() + sut.reportInitialDisplay() fixture.displayLinkWrapper.normalFrame() - XCTAssertEqual(ttidSpan?.timestamp, fixture.dateProvider.date()) - XCTAssertTrue(ttidSpan?.isFinished ?? false) + expect(ttidSpan?.isFinished) == true + expect(ttidSpan?.timestamp) == Date(timeIntervalSince1970: 9) + + assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 2_000) fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11)) sut.reportFullyDisplayed() - - assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 2_000) - assertMeasurement(tracer: tracer, name: "time_to_full_display", duration: 4_000) - - XCTAssertEqual(ttidSpan?.timestamp, Date(timeIntervalSince1970: 9)) - XCTAssertTrue(ttidSpan?.isFinished ?? false) - XCTAssertEqual(tracer.children.count, 2) + + // TTFD not reported yet cause we wait for the next frame + expect(sut.fullDisplaySpan?.startTimestamp) == ttidSpan?.startTimestamp + expect(sut.fullDisplaySpan?.timestamp) == nil + expect(tracer.measurements["time_to_full_display"]) == nil + + expect(Dynamic(self.fixture.framesTracker).listeners.count) == 1 } - func testreportFullDisplay_notWaitingForFullDisplay() { + func testReportFullDisplay_notWaitingForFullDisplay() throws { let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: false) - let tracer = fixture.tracer + let tracer = try fixture.getTracer() sut.start(for: tracer) - sut.reportReadyToDisplay() + sut.reportInitialDisplay() fixture.displayLinkWrapper.normalFrame() sut.reportFullyDisplayed() - XCTAssertNil(sut.fullDisplaySpan) - XCTAssertEqual(tracer.children.count, 1) + expect(sut.fullDisplaySpan) == nil + expect(tracer.children.count) == 1 + expect(tracer.measurements["time_to_full_display"]) == nil + + expect(Dynamic(self.fixture.framesTracker).listeners.count) == 0 } - - func testreportFullDisplay_waitingForFullDisplay() { + + func testReportFullDisplay_waitingForFullDisplay() throws { fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) - let tracer = fixture.tracer + let tracer = try fixture.getTracer() sut.start(for: tracer) fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 10)) - sut.reportReadyToDisplay() + sut.reportInitialDisplay() fixture.displayLinkWrapper.normalFrame() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11)) sut.reportFullyDisplayed() 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: 11)) - XCTAssertEqual(sut.fullDisplaySpan?.status, .ok) - - XCTAssertEqual(sut.fullDisplaySpan?.spanDescription, "UIViewController full display") - XCTAssertEqual(sut.fullDisplaySpan?.operation, SentrySpanOperationUILoadFullDisplay) - XCTAssertEqual(sut.fullDisplaySpan?.origin, "manual.ui.time_to_display") + expect(sut.fullDisplaySpan) != nil + expect(sut.fullDisplaySpan?.startTimestamp) == Date(timeIntervalSince1970: 9) + expect(sut.fullDisplaySpan?.timestamp) == Date(timeIntervalSince1970: 12) + expect(sut.fullDisplaySpan?.status) == .ok + + expect(sut.fullDisplaySpan?.spanDescription) == "UIViewController full display" + expect(sut.fullDisplaySpan?.operation) == SentrySpanOperationUILoadFullDisplay + expect(sut.fullDisplaySpan?.origin) == "manual.ui.time_to_display" + + assertMeasurement(tracer: tracer, name: "time_to_full_display", duration: 3_000) + + expect(Dynamic(self.fixture.framesTracker).listeners.count) == 0 } - - func testReportFullDisplay_waitingForFullDisplay_notReadyToDisplay() { + + func testWaitingForFullDisplay_ReportFullDisplayBeforeInitialDisplay() throws { + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) - let tracer = fixture.tracer + let tracer = try fixture.getTracer() sut.start(for: tracer) fixture.displayLinkWrapper.normalFrame() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11)) sut.reportFullyDisplayed() - - XCTAssertFalse(sut.fullDisplaySpan?.isFinished ?? true) - } - - func testReportFullDisplay_expires() { - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) - - let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) - let tracer = fixture.tracer - - sut.start(for: tracer) - - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 10)) - sut.reportReadyToDisplay() + fixture.displayLinkWrapper.normalFrame() - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11)) - sut.fullDisplaySpan?.finish(status: .deadlineExceeded) - - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 13)) - tracer.finish() - - XCTAssertEqual(sut.fullDisplaySpan?.startTimestamp, Date(timeIntervalSince1970: 9)) - XCTAssertEqual(sut.fullDisplaySpan?.timestamp, Date(timeIntervalSince1970: 10)) - XCTAssertEqual(sut.fullDisplaySpan?.spanDescription, "UIViewController full display - Deadline Exceeded") + expect(sut.fullDisplaySpan?.isFinished) == false + expect(sut.initialDisplaySpan?.isFinished) == false + + sut.reportInitialDisplay() + + expect(sut.fullDisplaySpan?.isFinished) == false + expect(sut.initialDisplaySpan?.isFinished) == false + + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 12)) + fixture.displayLinkWrapper.normalFrame() + + expect(sut.initialDisplaySpan?.isFinished) == true + expect(sut.initialDisplaySpan?.timestamp) == Date(timeIntervalSince1970: 12) + expect(sut.initialDisplaySpan?.status) == .ok + assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 3_000) + + expect(sut.fullDisplaySpan?.isFinished) == true + expect(sut.fullDisplaySpan?.timestamp) == Date(timeIntervalSince1970: 12) + expect(sut.fullDisplaySpan?.status) == .ok + assertMeasurement(tracer: tracer, name: "time_to_full_display", duration: 3_000) + + expect(Dynamic(self.fixture.framesTracker).listeners.count) == 0 } - func testCheckInitialTime() { + func testCheckInitialTime() throws { fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) fixture.dateProvider.driftTimeForEveryRead = true let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) - let tracer = fixture.tracer + let tracer = try fixture.getTracer() sut.start(for: tracer) - XCTAssertNotNil(sut.fullDisplaySpan) - XCTAssertEqual(sut.fullDisplaySpan?.startTimestamp, tracer.startTimestamp) - XCTAssertEqual(sut.initialDisplaySpan?.startTimestamp, tracer.startTimestamp) + expect(sut.fullDisplaySpan) != nil + expect(sut.fullDisplaySpan?.startTimestamp) == tracer.startTimestamp + expect(sut.initialDisplaySpan?.startTimestamp) == tracer.startTimestamp } + + func testReportFullyDisplayed_AfterTracerTimesOut() throws { + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) - func testFullDisplay_reportedBefore_initialDisplay() { - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 7)) - + let tracer = try fixture.getTracer() + let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) - let tracer = fixture.tracer + sut.start(for: tracer) - fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) - sut.reportFullyDisplayed() + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 10)) + sut.reportInitialDisplay() + fixture.displayLinkWrapper.normalFrame() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11)) - sut.reportReadyToDisplay() - fixture.displayLinkWrapper.normalFrame() - assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 4_000) - assertMeasurement(tracer: tracer, name: "time_to_full_display", duration: 4_000) + // Timeout for tracer times out + fixture.timerFactory.fire() - XCTAssertEqual(sut.initialDisplaySpan?.timestamp, fixture.dateProvider.date()) - XCTAssertEqual(sut.fullDisplaySpan?.timestamp, sut.initialDisplaySpan?.timestamp) + fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 12)) + sut.reportFullyDisplayed() + + let ttidSpan = sut.initialDisplaySpan + expect(ttidSpan?.startTimestamp) == Date(timeIntervalSince1970: 9) + expect(ttidSpan?.timestamp) == Date(timeIntervalSince1970: 10) + expect(ttidSpan?.status) == .ok + assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 1_000) + + let ttfdSpan = sut.fullDisplaySpan + expect(ttfdSpan?.startTimestamp) == ttidSpan?.startTimestamp + expect(ttfdSpan?.timestamp) == ttidSpan?.timestamp + expect(ttfdSpan?.status) == .deadlineExceeded + expect(ttfdSpan?.spanDescription) == "UIViewController full display - Deadline Exceeded" + expect(ttfdSpan?.operation) == SentrySpanOperationUILoadFullDisplay + expect(ttfdSpan?.origin) == "manual.ui.time_to_display" + + assertMeasurement(tracer: tracer, name: "time_to_full_display", duration: 1_000) } - - func testReportFullyDisplayed_afterFinishingTracer_withWaitForChildren() throws { + + func testNotWaitingForFullyDisplayed_AfterTracerTimesOut() throws { fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 9)) - let options = Options() - let hub = TestHub(client: SentryClient(options: options, fileManager: try TestFileManager(options: options), deleteOldEnvelopeItems: false), andScope: nil) - let tracer = SentryTracer(transactionContext: TransactionContext(operation: "Test Operation"), hub: hub, configuration: SentryTracerConfiguration(block: { config in - config.waitForChildren = true - })) - let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: true) + let tracer = try fixture.getTracer() + + let sut = fixture.getSut(for: UIViewController(), waitForFullDisplay: false) sut.start(for: tracer) fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 10)) - sut.reportReadyToDisplay() + sut.reportInitialDisplay() fixture.displayLinkWrapper.normalFrame() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 11)) - tracer.finish() + // Timeout for tracer times out + fixture.timerFactory.fire() fixture.dateProvider.setDate(date: Date(timeIntervalSince1970: 12)) sut.reportFullyDisplayed() - - let transaction = hub.capturedTransactionsWithScope.first?.transaction - let measurements = transaction?["measurements"] as? [String: Any] - let ttid = measurements?["time_to_initial_display"] as? [String: Any] - let ttfd = measurements?["time_to_full_display"] as? [String: Any] - - XCTAssertEqual(ttid?["value"] as? Int, 1_000) - XCTAssertEqual(ttfd?["value"] as? Int, 3_000) + + assertMeasurement(tracer: tracer, name: "time_to_initial_display", duration: 1_000) + let ttidSpan = sut.initialDisplaySpan + expect(ttidSpan?.startTimestamp) == Date(timeIntervalSince1970: 9) + expect(ttidSpan?.timestamp) == Date(timeIntervalSince1970: 10) + expect(ttidSpan?.status) == .ok + + expect(sut.fullDisplaySpan) == nil + expect(tracer.measurements["time_to_full_display"]) == nil } func assertMeasurement(tracer: SentryTracer, name: String, duration: TimeInterval) { - XCTAssertEqual(tracer.measurements[name]?.value, NSNumber(value: duration)) - XCTAssertEqual(tracer.measurements[name]?.unit?.unit, "millisecond") - + expect(tracer.measurements[name]?.value) == NSNumber(value: duration) + expect(tracer.measurements[name]?.unit?.unit) == "millisecond" } } diff --git a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryUIViewControllerPerformanceTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryUIViewControllerPerformanceTrackerTests.swift index c9921cb8f35..6262eb35479 100644 --- a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryUIViewControllerPerformanceTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryUIViewControllerPerformanceTrackerTests.swift @@ -1,5 +1,6 @@ #if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) +import Nimble import ObjectiveC import SentryTestUtils import XCTest @@ -21,6 +22,7 @@ class SentryUIViewControllerPerformanceTrackerTests: XCTestCase { let spanName = "spanName" let spanOperation = "spanOperation" let origin = "auto.ui.view_controller" + let frameDuration = 0.0016 private class Fixture { @@ -251,11 +253,11 @@ class SentryUIViewControllerPerformanceTrackerTests: XCTestCase { callbackExpectation.fulfill() } try assertSpanDuration(span: lastSpan, expectedDuration: 5) - try assertSpanDuration(span: transactionSpan, expectedDuration: 22) + try assertSpanDuration(span: transactionSpan, expectedDuration: 22 + frameDuration) wait(for: [callbackExpectation], timeout: 0) } - + func testReportFullyDisplayed() { let sut = fixture.getSut() sut.enableWaitForFullDisplay = true @@ -267,11 +269,17 @@ class SentryUIViewControllerPerformanceTrackerTests: XCTestCase { let spans = self.getStack(tracker) tracer = spans.first as? SentryTracer } + sut.viewControllerViewWillAppear(viewController) { + self.advanceTime(bySeconds: 0.1) + } sut.reportFullyDisplayed() reportFrame() + let expectedTTFDTimestamp = fixture.dateProvider.date() - XCTAssertTrue(tracer?.children[1].isFinished ?? false) + let ttfdSpan = tracer?.children[1] + expect(ttfdSpan?.isFinished) == true + expect(ttfdSpan?.timestamp) == expectedTTFDTimestamp } func testSecondViewController() { @@ -598,7 +606,7 @@ class SentryUIViewControllerPerformanceTrackerTests: XCTestCase { let timestamp = try XCTUnwrap(span.timestamp) let startTimestamp = try XCTUnwrap(span.startTimestamp) let duration = timestamp.timeIntervalSince(startTimestamp) - XCTAssertEqual(duration, expectedDuration) + expect(duration).to(beCloseTo(expectedDuration, within: 0.001)) } private func assertTrackerIsEmpty(_ tracker: SentryPerformanceTracker) { @@ -621,6 +629,7 @@ class SentryUIViewControllerPerformanceTrackerTests: XCTestCase { } private func reportFrame() { + advanceTime(bySeconds: self.frameDuration) Dynamic(SentryDependencyContainer.sharedInstance().framesTracker).displayLinkCallback() } } From 15d217b24e11996ea337711019ec00622756a19a Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 19 Dec 2023 10:45:17 +0100 Subject: [PATCH 2/2] 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 | 1 + Sources/Sentry/SentryTimeToDisplayTracker.m | 16 +++- Sources/Sentry/SentryTracer.m | 12 +-- .../SentryTimeToDisplayTrackerTest.swift | 75 ++++++++++++++++++- 4 files changed, 91 insertions(+), 13 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index dfffc1bee6e..e1aa75c54e6 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/Sources/Sentry/SentryTimeToDisplayTracker.m b/Sources/Sentry/SentryTimeToDisplayTracker.m index 1bf922378e6..4b9b21569f1 100644 --- a/Sources/Sentry/SentryTimeToDisplayTracker.m +++ b/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]; } diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 78031ac82b8..3f8860963ce 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/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. diff --git a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift index c1e48bc0f7c..adc04dbc21d 100644 --- a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift +++ b/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)