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.
getsentry · Aug 13, 2024 · 7d7699a · 7d7699a
1 parent 02671d8
commit 7d7699a
Show file tree

Hide file tree

Showing 6 changed files with 88 additions and 27 deletions.
diff --git 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
@@ -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
@@ -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<SentryDelayedFrame *> *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<SentryDelayedFrame *> *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
@@ -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
@@ -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,15 +47,13 @@ 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.
  */
 - (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
@@ -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()