From 15d217b24e11996ea337711019ec00622756a19a Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 19 Dec 2023 10:45:17 +0100 Subject: [PATCH] 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)