diff --git a/CHANGELOG.md b/CHANGELOG.md index 5313a363add..7bab17f3de0 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/Sources/Sentry/SentryDelayedFramesTracker.m b/Sources/Sentry/SentryDelayedFramesTracker.m index 01e64425d1a..4974b2b4a41 100644 --- a/Sources/Sentry/SentryDelayedFramesTracker.m +++ b/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 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