diff --git a/CHANGELOG.md b/CHANGELOG.md index 8b9252b1e91..519738f1a13 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,7 @@ ### Fixes - Session replay not redacting buttons and other non UILabel texts (#4277) +- Rarely reporting too long frame delays (#4278) by fixing a race condition in the frames tracking logic. ## 8.33.0 diff --git a/SentryTestUtils/TestDisplayLinkWrapper.swift b/SentryTestUtils/TestDisplayLinkWrapper.swift index 246201310d5..d0bcc16f043 100644 --- a/SentryTestUtils/TestDisplayLinkWrapper.swift +++ b/SentryTestUtils/TestDisplayLinkWrapper.swift @@ -114,6 +114,11 @@ public class TestDisplayLinkWrapper: SentryDisplayLinkWrapper { call() return fastestFrozenFrameDuration } + + public func frameWith(delay: Double) { + dateProvider.advance(by: currentFrameRate.tickDuration + delay) + call() + } /// There's no upper bound for a frozen frame, except maybe for the watchdog time limit. /// - parameter extraTime: the additional time to add to the frozen frame threshold when simulating a frozen frame. diff --git a/Sources/Sentry/SentryDelayedFramesTracker.m b/Sources/Sentry/SentryDelayedFramesTracker.m index 5a515e5cd55..bf795f006c6 100644 --- a/Sources/Sentry/SentryDelayedFramesTracker.m +++ b/Sources/Sentry/SentryDelayedFramesTracker.m @@ -3,6 +3,7 @@ #if SENTRY_HAS_UIKIT # import "SentryDelayedFrame.h" +# import "SentryInternalCDefines.h" # import "SentryLog.h" # import "SentrySwift.h" # import "SentryTime.h" @@ -15,6 +16,8 @@ @property (nonatomic, assign) CFTimeInterval keepDelayedFramesDuration; @property (nonatomic, strong, readonly) SentryCurrentDateProvider *dateProvider; @property (nonatomic, strong) NSMutableArray *delayedFrames; +@property (nonatomic) uint64_t lastDelayedFrameSystemTimestamp; +@property (nonatomic) uint64_t previousFrameSystemTimestamp; @end @@ -31,6 +34,20 @@ - (instancetype)initWithKeepDelayedFramesDuration:(CFTimeInterval)keepDelayedFra return self; } +- (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.") +{ + _previousFrameSystemTimestamp = previousFrameSystemTimestamp; +} + +- (uint64_t)getPreviousFrameSystemTimestamp SENTRY_DISABLE_THREAD_SANITIZER( + "We don't want to synchronize the access to this property to avoid slowing down the main " + "thread.") +{ + return _previousFrameSystemTimestamp; +} + - (void)resetDelayedFramesTimeStamps { _delayedFrames = [NSMutableArray array]; @@ -42,9 +59,13 @@ - (void)resetDelayedFramesTimeStamps } - (void)recordDelayedFrame:(uint64_t)startSystemTimestamp - expectedDuration:(CFTimeInterval)expectedDuration - actualDuration:(CFTimeInterval)actualDuration + thisFrameSystemTimestamp:(uint64_t)thisFrameSystemTimestamp + expectedDuration:(CFTimeInterval)expectedDuration + actualDuration:(CFTimeInterval)actualDuration { + // This @synchronized block only gets called for delayed frames. + // We accept the tradeoff of slowing down the main thread a bit to + // record the frame delay data. @synchronized(self.delayedFrames) { [self removeOldDelayedFrames]; @@ -53,6 +74,8 @@ - (void)recordDelayedFrame:(uint64_t)startSystemTimestamp expectedDuration:expectedDuration actualDuration:actualDuration]; [self.delayedFrames addObject:delayedFrame]; + self.lastDelayedFrameSystemTimestamp = thisFrameSystemTimestamp; + self.previousFrameSystemTimestamp = thisFrameSystemTimestamp; } } @@ -92,7 +115,6 @@ - (void)removeOldDelayedFrames - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp endSystemTimestamp:(uint64_t)endSystemTimestamp isRunning:(BOOL)isRunning - previousFrameSystemTimestamp:(uint64_t)previousFrameSystemTimestamp slowFrameThreshold:(CFTimeInterval)slowFrameThreshold { CFTimeInterval cantCalculateFrameDelayReturnValue = -1.0; @@ -114,13 +136,20 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp return cantCalculateFrameDelayReturnValue; } - if (previousFrameSystemTimestamp == 0) { - SENTRY_LOG_DEBUG(@"Not calculating frames delay because no frames yet recorded."); - return cantCalculateFrameDelayReturnValue; - } + // Make a local copy because this method can be called on a background thread and the value + // could change. + uint64_t localPreviousFrameSystemTimestamp; NSMutableArray *frames; @synchronized(self.delayedFrames) { + + localPreviousFrameSystemTimestamp = self.previousFrameSystemTimestamp; + + if (localPreviousFrameSystemTimestamp == 0) { + SENTRY_LOG_DEBUG(@"Not calculating frames delay because no frames yet recorded."); + return cantCalculateFrameDelayReturnValue; + } + uint64_t oldestDelayedFrameStartTimestamp = UINT64_MAX; SentryDelayedFrame *oldestDelayedFrame = self.delayedFrames.firstObject; if (oldestDelayedFrame != nil) { @@ -139,10 +168,10 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp // Add a delayed frame for a potentially ongoing but not recorded delayed frame SentryDelayedFrame *currentFrameDelay = [[SentryDelayedFrame alloc] - initWithStartTimestamp:previousFrameSystemTimestamp + initWithStartTimestamp:localPreviousFrameSystemTimestamp expectedDuration:slowFrameThreshold actualDuration:nanosecondsToTimeInterval( - endSystemTimestamp - previousFrameSystemTimestamp)]; + endSystemTimestamp - localPreviousFrameSystemTimestamp)]; [frames addObject:currentFrameDelay]; diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index 44f1e911ef8..7edacf06554 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -96,19 +96,6 @@ - (void)setDisplayLinkWrapper:(SentryDisplayLinkWrapper *)displayLinkWrapper { _displayLinkWrapper = displayLinkWrapper; } -- (void)setPreviousFrameSystemTimestamp:(uint64_t)previousFrameSystemTimestamp - SENTRY_DISABLE_THREAD_SANITIZER("As you can only disable the thread sanitizer for methods, we " - "must manually create the setter here.") -{ - _previousFrameSystemTimestamp = previousFrameSystemTimestamp; -} - -- (uint64_t)getPreviousFrameSystemTimestamp SENTRY_DISABLE_THREAD_SANITIZER( - "As you can only disable the thread sanitizer for methods, we must manually create the getter " - "here.") -{ - return _previousFrameSystemTimestamp; -} - (void)resetFrames { @@ -193,6 +180,7 @@ - (void)displayLinkCallback if (self.previousFrameTimestamp == SentryPreviousFrameInitialValue) { self.previousFrameTimestamp = thisFrameTimestamp; self.previousFrameSystemTimestamp = thisFrameSystemTimestamp; + [self.delayedFramesTracker setPreviousFrameSystemTimestamp:thisFrameSystemTimestamp]; [self reportNewFrame]; return; } @@ -254,8 +242,11 @@ - (void)displayLinkCallback if (frameDuration > slowFrameThreshold(_currentFrameRate)) { [self.delayedFramesTracker recordDelayedFrame:self.previousFrameSystemTimestamp + thisFrameSystemTimestamp:thisFrameSystemTimestamp expectedDuration:slowFrameThreshold(_currentFrameRate) actualDuration:frameDuration]; + } else { + [self.delayedFramesTracker setPreviousFrameSystemTimestamp:thisFrameSystemTimestamp]; } _totalFrames++; @@ -314,7 +305,6 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp return [self.delayedFramesTracker getFramesDelay:startSystemTimestamp endSystemTimestamp:endSystemTimestamp isRunning:_isRunning - previousFrameSystemTimestamp:self.previousFrameSystemTimestamp slowFrameThreshold:slowFrameThreshold(_currentFrameRate)]; } diff --git a/Sources/Sentry/include/SentryDelayedFramesTracker.h b/Sources/Sentry/include/SentryDelayedFramesTracker.h index bb02b3bf7f6..17d76c34ac1 100644 --- a/Sources/Sentry/include/SentryDelayedFramesTracker.h +++ b/Sources/Sentry/include/SentryDelayedFramesTracker.h @@ -23,8 +23,11 @@ SENTRY_NO_INIT - (void)resetDelayedFramesTimeStamps; - (void)recordDelayedFrame:(uint64_t)startSystemTimestamp - expectedDuration:(CFTimeInterval)expectedDuration - actualDuration:(CFTimeInterval)actualDuration; + thisFrameSystemTimestamp:(uint64_t)thisFrameSystemTimestamp + expectedDuration:(CFTimeInterval)expectedDuration + actualDuration:(CFTimeInterval)actualDuration; + +- (void)setPreviousFrameSystemTimestamp:(uint64_t)previousFrameSystemTimestamp; /** * This method returns the duration of all delayed frames between startSystemTimestamp and @@ -44,7 +47,6 @@ SENTRY_NO_INIT * delay. * @param endSystemTimestamp The end system time stamp for the time interval to query frames delay. * @param isRunning Wether the frames tracker is running or not. - * @param previousFrameSystemTimestamp The system timestamp of the previous frame. * @param slowFrameThreshold The threshold for a slow frame. For 60 fps this is roughly 16.67 ms. * * @return the frames delay duration or -1 if it can't calculate the frames delay. @@ -52,7 +54,6 @@ SENTRY_NO_INIT - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp endSystemTimestamp:(uint64_t)endSystemTimestamp isRunning:(BOOL)isRunning - previousFrameSystemTimestamp:(uint64_t)previousFrameSystemTimestamp slowFrameThreshold:(CFTimeInterval)slowFrameThreshold; @end diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index 2c7774fd9b1..790ae532a7a 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -534,6 +534,41 @@ class SentryFramesTrackerTests: XCTestCase { wait(for: [expectation], timeout: 3.0) } + func testGetFramesDelayOnTightLoop_WhileKeepAddingDelayedFrames() { + let displayLink = fixture.displayLinkWrapper + let dateProvider = fixture.dateProvider + + let sut = fixture.sut + sut.start() + + for _ in 0..<100 { + displayLink.normalFrame() + } + + let expectation = expectation(description: "Get Frames Delays") + + DispatchQueue.global().async { + + for _ in 0..<1_000 { + + let endSystemTimestamp = dateProvider.systemTime() + let startSystemTimestamp = endSystemTimestamp - timeIntervalToNanoseconds(1.0) + + let frameDelay = sut.getFramesDelay(startSystemTimestamp, endSystemTimestamp: endSystemTimestamp) + + XCTAssertLessThanOrEqual(frameDelay, 1.0) + } + + expectation.fulfill() + } + + for _ in 0..<1_000 { + displayLink.frameWith(delay: 1.0) + } + + wait(for: [expectation], timeout: 3.0) + } + func testAddMultipleListeners_AllCalledWithSameDate() { let sut = fixture.sut let listener1 = FrameTrackerListener()