From 33d75f93bcd1e01805e5e9bd380d4d329bbc907b Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Wed, 8 Oct 2025 06:42:04 +0200 Subject: [PATCH 1/2] fix: Wrong Frame Delay when becoming active The SDK reported false frame delay statistics when it moved from the background to the foreground, which also led to falsely reported app hangs. Fixes GH-6345 --- CHANGELOG.md | 1 + Sources/Sentry/SentryDelayedFramesTracker.m | 23 +- Sources/Sentry/SentryFramesTracker.m | 9 +- .../include/SentryDelayedFramesTracker.h | 4 +- .../SentryFramesTrackerTests.swift | 198 +++++++++++++++--- 5 files changed, 189 insertions(+), 46 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e37ef9eafcc..9a40377ece9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,6 +18,7 @@ - Fixes warnings about minimum OS version being lower than Xcode supported version (#5591) - Fix rendering method for fast view rendering (#6360) +- Fix wrong Frame Delay when becoming active, which lead to false reported app hangs when the app moves to the foreground after being in the background (#6381) ## 8.56.2 diff --git a/Sources/Sentry/SentryDelayedFramesTracker.m b/Sources/Sentry/SentryDelayedFramesTracker.m index 01e64425d1a..fcfb789d646 100644 --- a/Sources/Sentry/SentryDelayedFramesTracker.m +++ b/Sources/Sentry/SentryDelayedFramesTracker.m @@ -28,11 +28,22 @@ - (instancetype)initWithKeepDelayedFramesDuration:(CFTimeInterval)keepDelayedFra if (self = [super init]) { _keepDelayedFramesDuration = keepDelayedFramesDuration; _dateProvider = dateProvider; - [self resetDelayedFramesTimeStamps]; + [self reset]; } return self; } +- (void)reset +{ + _delayedFrames = [NSMutableArray array]; + _previousFrameSystemTimestamp = 0; + SentryDelayedFrame *initialFrame = + [[SentryDelayedFrame alloc] initWithStartTimestamp:[self.dateProvider systemTime] + expectedDuration:0 + actualDuration:0]; + [_delayedFrames addObject:initialFrame]; +} + - (void)setPreviousFrameSystemTimestamp:(uint64_t)previousFrameSystemTimestamp SENTRY_DISABLE_THREAD_SANITIZER("We don't want to synchronize the access to this property to " "avoid slowing down the main thread.") @@ -47,16 +58,6 @@ - (uint64_t)getPreviousFrameSystemTimestamp SENTRY_DISABLE_THREAD_SANITIZER( return _previousFrameSystemTimestamp; } -- (void)resetDelayedFramesTimeStamps -{ - _delayedFrames = [NSMutableArray array]; - SentryDelayedFrame *initialFrame = - [[SentryDelayedFrame alloc] initWithStartTimestamp:[self.dateProvider systemTime] - expectedDuration:0 - actualDuration:0]; - [_delayedFrames addObject:initialFrame]; -} - - (void)recordDelayedFrame:(uint64_t)startSystemTimestamp thisFrameSystemTimestamp:(uint64_t)thisFrameSystemTimestamp expectedDuration:(CFTimeInterval)expectedDuration diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index 0c31c171f72..e14042f2ff5 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -104,7 +104,7 @@ - (void)resetFrames [self resetProfilingTimestampsInternal]; # endif // SENTRY_TARGET_PROFILING_SUPPORTED - [self.delayedFramesTracker resetDelayedFramesTimeStamps]; + [self.delayedFramesTracker reset]; } # if SENTRY_TARGET_PROFILING_SUPPORTED @@ -164,6 +164,7 @@ - (void)unpause } _isRunning = YES; + // Reset the previous frame timestamp to avoid wrong metrics being collected self.previousFrameTimestamp = SentryPreviousFrameInitialValue; [_displayLinkWrapper linkWithTarget:self selector:@selector(displayLinkCallback)]; @@ -320,6 +321,11 @@ - (void)removeListener:(id)listener - (void)pause { _isRunning = NO; + + // When the frames tracker is paused, we must reset the delayed frames tracker since accurate + // frame delay statistics cannot be provided, as we can't account for events during the pause. + [self.delayedFramesTracker reset]; + [self.displayLinkWrapper invalidate]; } @@ -332,7 +338,6 @@ - (void)stop _isStarted = NO; [self pause]; - [self.delayedFramesTracker resetDelayedFramesTimeStamps]; // Remove the observers with the most specific detail possible, see // https://developer.apple.com/documentation/foundation/nsnotificationcenter/1413994-removeobserver diff --git a/Sources/Sentry/include/SentryDelayedFramesTracker.h b/Sources/Sentry/include/SentryDelayedFramesTracker.h index efd9f7b5a70..ab36c529005 100644 --- a/Sources/Sentry/include/SentryDelayedFramesTracker.h +++ b/Sources/Sentry/include/SentryDelayedFramesTracker.h @@ -21,8 +21,6 @@ SENTRY_NO_INIT - (instancetype)initWithKeepDelayedFramesDuration:(CFTimeInterval)keepDelayedFramesDuration dateProvider:(id)dateProvider; -- (void)resetDelayedFramesTimeStamps; - - (void)recordDelayedFrame:(uint64_t)startSystemTimestamp thisFrameSystemTimestamp:(uint64_t)thisFrameSystemTimestamp expectedDuration:(CFTimeInterval)expectedDuration @@ -30,6 +28,8 @@ SENTRY_NO_INIT - (void)setPreviousFrameSystemTimestamp:(uint64_t)previousFrameSystemTimestamp; +- (void)reset; + /** * This method returns the duration of all delayed frames between startSystemTimestamp and * endSystemTimestamp. diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index 448c5623cc0..7f220bbe593 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -3,6 +3,9 @@ @_spi(Private) import SentryTestUtils import XCTest +// swiftlint:disable file_length +// This test class also includes tests for delayed frames calculation which is quite complex. + #if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) class SentryFramesTrackerTests: XCTestCase { @@ -518,7 +521,167 @@ class SentryFramesTrackerTests: XCTestCase { let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) XCTAssertEqual(actualFrameDelay.delayDuration, -1.0) } - + + func testGetFramesDelay_WhenMovingFromBackgroundToForeground_BeforeDisplayLinkCalled() { + // Arrange + let sut = fixture.sut + sut.start() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + let startSystemTime = fixture.dateProvider.systemTime() + + fixture.notificationCenter.post(Notification(name: CrossPlatformApplication.willResignActiveNotification)) + + // Simulate app staying in background for 2 seconds + fixture.dateProvider.advance(by: 2.0) + + fixture.notificationCenter.post(Notification(name: CrossPlatformApplication.didBecomeActiveNotification)) + let endSystemTime = fixture.dateProvider.systemTime() + + // Act + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + + // Assert + + // The frames tracer starts subscribing to the display link when an app moves to the foreground. Since + // display link callbacks only occur when a new frame is drawn, it can take a couple of milliseconds + // for the first display link callback to occur. We can only calculate frame statistics when having at + // least one display link callback, as this marks the start of a new frame. + XCTAssertEqual(actualFrameDelay.delayDuration, -1.0, accuracy: 0.0001) + } + + func testGetFramesDelay_WhenMovingFromBackgroundToForeground_FirstFrameIsDrawing() { + // Arrange + let sut = fixture.sut + sut.start() + + // Simulate some frames to establish system timestamps + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + fixture.notificationCenter.post(Notification(name: CrossPlatformApplication.willResignActiveNotification)) + + // Simulate app staying in background for 2 seconds + fixture.dateProvider.advance(by: 2.0) + + fixture.notificationCenter.post(Notification(name: CrossPlatformApplication.didBecomeActiveNotification)) + + displayLink.call() + + let startSystemTime = fixture.dateProvider.systemTime() + fixture.dateProvider.advance(by: 0.01) + let endSystemTime = fixture.dateProvider.systemTime() + + // Act + let frameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + + // The first is currently drawn, but it's not delayed yet. Therefore, 0 frame delay. + XCTAssertEqual(frameDelay.delayDuration, 0.0, accuracy: 0.0001) + } + + func testGetFramesDelay_WhenMovingFromBackgroundToForeground_FirstNormalFrameDrawn() { + // Arrange + let sut = fixture.sut + sut.start() + + // Simulate some frames to establish system timestamps + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + fixture.notificationCenter.post(Notification(name: CrossPlatformApplication.willResignActiveNotification)) + + // Simulate app staying in background for 2 seconds + fixture.dateProvider.advance(by: 2.0) + + fixture.notificationCenter.post(Notification(name: CrossPlatformApplication.didBecomeActiveNotification)) + + displayLink.call() + + // The delayed frames tracker should also have its previous frame system timestamp reset + // This prevents false delay calculations after unpausing + let startSystemTime = fixture.dateProvider.systemTime() + displayLink.normalFrame() + let endSystemTime = fixture.dateProvider.systemTime() + + // Act + let frameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + + // Assert + // Normal frame is drawn, no delay + XCTAssertEqual(frameDelay.delayDuration, 0.0, accuracy: 0.0001) + } + + func testGetFramesDelay_WhenMovingFromBackgroundToForeground_FirstFrameIsSlow() { + // Arrange + let sut = fixture.sut + sut.start() + + // Simulate some frames to establish system timestamps + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + fixture.notificationCenter.post(Notification(name: CrossPlatformApplication.willResignActiveNotification)) + + // Simulate app staying in background for 2 seconds + fixture.dateProvider.advance(by: 2.0) + + fixture.notificationCenter.post(Notification(name: CrossPlatformApplication.didBecomeActiveNotification)) + + displayLink.call() + + // The delayed frames tracker should also have its previous frame system timestamp reset + // This prevents false delay calculations after unpausing + let startSystemTime = fixture.dateProvider.systemTime() + _ = displayLink.slowestSlowFrame() + let endSystemTime = fixture.dateProvider.systemTime() + + // Act + let frameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + + let expectedDelay = fixture.displayLinkWrapper.slowestSlowFrameDuration - slowFrameThreshold(fixture.displayLinkWrapper.currentFrameRate.rawValue) + + // Assert + XCTAssertEqual(frameDelay.delayDuration, expectedDelay, accuracy: 0.0001) + } + + func testGetFramesDelay_WhenMovingFromBackgroundToForeground_DelayBeforeBackgroundNotIncluded() { + // Arrange + let sut = fixture.sut + sut.start() + + // Simulate some frames to establish system timestamps + let displayLink = fixture.displayLinkWrapper + displayLink.call() + + let startSystemTime = fixture.dateProvider.systemTime() + + _ = displayLink.slowestSlowFrame() + + fixture.notificationCenter.post(Notification(name: CrossPlatformApplication.willResignActiveNotification)) + + // Simulate app staying in background for 2 seconds + fixture.dateProvider.advance(by: 2.0) + + fixture.notificationCenter.post(Notification(name: CrossPlatformApplication.didBecomeActiveNotification)) + + displayLink.call() + + _ = displayLink.slowestSlowFrame() + let endSystemTime = fixture.dateProvider.systemTime() + + // Act + let frameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + + // Assert + XCTAssertEqual(frameDelay.delayDuration, -1.0, accuracy: 0.0001) + } + func testFrameDelay_GetInfoFromBackgroundThreadWhileAdding() { let sut = fixture.sut sut.start() @@ -580,7 +743,7 @@ class SentryFramesTrackerTests: XCTestCase { wait(for: [expectation], timeout: 3.0) } - + func testAddMultipleListeners_AllCalledWithSameDate() { let sut = fixture.sut let listener1 = FrameTrackerListener() @@ -804,35 +967,6 @@ class SentryFramesTrackerTests: XCTestCase { // Should not detect any slow or frozen frames from the pauses try assert(slow: 0, frozen: 0, total: 4) } - - func testUnpause_WithDelayedFramesTracker_ResetsPreviousFrameSystemTimestamp() { - let sut = fixture.sut - sut.start() - - // Simulate some frames to establish system timestamps - fixture.displayLinkWrapper.call() - fixture.displayLinkWrapper.normalFrame() - - // Pause the tracker - fixture.notificationCenter.post(Notification(name: CrossPlatformApplication.willResignActiveNotification)) - - // Advance time significantly - fixture.dateProvider.advance(by: 5.0) - - // Unpause the tracker - fixture.notificationCenter.post(Notification(name: CrossPlatformApplication.didBecomeActiveNotification)) - - // The delayed frames tracker should also have its previous frame system timestamp reset - // This prevents false delay calculations after unpausing - let startSystemTime = fixture.dateProvider.systemTime() - fixture.dateProvider.advance(by: 0.001) - let endSystemTime = fixture.dateProvider.systemTime() - - let frameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) - - // Should not report any delay from the pause period - XCTAssertEqual(frameDelay.delayDuration, 0.001, accuracy: 0.0001) - } #if os(iOS) || os(macOS) || targetEnvironment(macCatalyst) func testResetProfilingTimestamps_FromBackgroundThread() { @@ -941,3 +1075,5 @@ private extension SentryFramesTrackerTests { } #endif + +// swiftlint:enable file_length From f5d6e04dee65ff9a4276a43dec401c74e60c84ff Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Wed, 8 Oct 2025 07:33:16 +0200 Subject: [PATCH 2/2] make thread safe --- Sources/Sentry/SentryDelayedFramesTracker.m | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) diff --git a/Sources/Sentry/SentryDelayedFramesTracker.m b/Sources/Sentry/SentryDelayedFramesTracker.m index fcfb789d646..4974b2b4a41 100644 --- a/Sources/Sentry/SentryDelayedFramesTracker.m +++ b/Sources/Sentry/SentryDelayedFramesTracker.m @@ -28,6 +28,7 @@ - (instancetype)initWithKeepDelayedFramesDuration:(CFTimeInterval)keepDelayedFra if (self = [super init]) { _keepDelayedFramesDuration = keepDelayedFramesDuration; _dateProvider = dateProvider; + _delayedFrames = [NSMutableArray new]; [self reset]; } return self; @@ -35,13 +36,16 @@ - (instancetype)initWithKeepDelayedFramesDuration:(CFTimeInterval)keepDelayedFra - (void)reset { - _delayedFrames = [NSMutableArray array]; - _previousFrameSystemTimestamp = 0; - SentryDelayedFrame *initialFrame = - [[SentryDelayedFrame alloc] initWithStartTimestamp:[self.dateProvider systemTime] - expectedDuration:0 - actualDuration:0]; - [_delayedFrames addObject:initialFrame]; + @synchronized(self.delayedFrames) { + _previousFrameSystemTimestamp = 0; + SentryDelayedFrame *initialFrame = + [[SentryDelayedFrame alloc] initWithStartTimestamp:[self.dateProvider systemTime] + expectedDuration:0 + actualDuration:0]; + + [_delayedFrames removeAllObjects]; + [_delayedFrames addObject:initialFrame]; + } } - (void)setPreviousFrameSystemTimestamp:(uint64_t)previousFrameSystemTimestamp