Merge 7d7699a into 02671d8

getsentry · Aug 13, 2024 · f8d77f9 · f8d77f9
2 parents 02671d8 + 7d7699a
commit f8d77f9
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()