From 7d7699a9f8355925c5fa00dcef93f1594408dfe6 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 13 Aug 2024 15:21:23 +0200 Subject: [PATCH] fix: Rarely reporting too long frame delays Fix a race condition in the SentryFramesTracker and SentryDelayedFramesTracker that sometimes leads to frame delay durations longer than the queried interval of start and end time. This is fixed by moving the previousFrameSystemTimestamp down to the SentryDelayedFramesTracker so we can adequately synchronize it without acquiring extra locks on the main thread. --- CHANGELOG.md | 1 + SentryTestUtils/TestDisplayLinkWrapper.swift | 5 ++ Sources/Sentry/SentryDelayedFramesTracker.m | 47 +++++++++++++++---- Sources/Sentry/SentryFramesTracker.m | 18 ++----- .../include/SentryDelayedFramesTracker.h | 9 ++-- .../SentryFramesTrackerTests.swift | 35 ++++++++++++++ 6 files changed, 88 insertions(+), 27 deletions(-) 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()