fix: Wrong Frame Delay when becoming active

CHANGELOG.md

@@ -22,6 +22,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)
 
 ### Improvements
 

Sources/Sentry/SentryDelayedFramesTracker.m

@@ -28,11 +28,26 @@ - (instancetype)initWithKeepDelayedFramesDuration:(CFTimeInterval)keepDelayedFra
     if (self = [super init]) {
         _keepDelayedFramesDuration = keepDelayedFramesDuration;
         _dateProvider = dateProvider;
-        [self resetDelayedFramesTimeStamps];
+        _delayedFrames = [NSMutableArray new];
+        [self reset];
     }
     return self;
 }
 
+- (void)reset
+{
+    @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
     SENTRY_DISABLE_THREAD_SANITIZER("We don't want to synchronize the access to this property to "
                                     "avoid slowing down the main thread.")
@@ -47,16 +62,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

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<SentryFramesTrackerListener>)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

Sources/Sentry/include/SentryDelayedFramesTracker.h

@@ -21,15 +21,15 @@ SENTRY_NO_INIT
 - (instancetype)initWithKeepDelayedFramesDuration:(CFTimeInterval)keepDelayedFramesDuration
                                      dateProvider:(id<SentryCurrentDateProvider>)dateProvider;
 
-- (void)resetDelayedFramesTimeStamps;
-
 - (void)recordDelayedFrame:(uint64_t)startSystemTimestamp
     thisFrameSystemTimestamp:(uint64_t)thisFrameSystemTimestamp
             expectedDuration:(CFTimeInterval)expectedDuration
               actualDuration:(CFTimeInterval)actualDuration;
 
 - (void)setPreviousFrameSystemTimestamp:(uint64_t)previousFrameSystemTimestamp;
 
+- (void)reset;
+
 /**
  * This method returns the duration of all delayed frames between startSystemTimestamp and
  * endSystemTimestamp.

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