feat: Add frames delay to span data (#3496)

Also, fix a couple of edge cases when calculating the frames delay when
An ongoing delayed frame has not yet been recorded.

CHANGELOG.md

@@ -4,7 +4,7 @@
 
 ### Features
 
-- Add frames delay to transactions (#3487)
+- Add frames delay to transactions and spans (#3487, #3496)
 - Add slow and frozen frames to spans (#3450, #3478)
 ## 8.17.2
 

Sources/Sentry/SentryDelayedFramesTracker.m

@@ -92,8 +92,7 @@ - (void)removeOldDelayedFrames
 - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp
               endSystemTimestamp:(uint64_t)endSystemTimestamp
                        isRunning:(BOOL)isRunning
-              thisFrameTimestamp:(CFTimeInterval)thisFrameTimestamp
-          previousFrameTimestamp:(CFTimeInterval)previousFrameTimestamp
+    previousFrameSystemTimestamp:(uint64_t)previousFrameSystemTimestamp
               slowFrameThreshold:(CFTimeInterval)slowFrameThreshold
 {
     CFTimeInterval cantCalculateFrameDelayReturnValue = -1.0;
@@ -115,12 +114,12 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp
         return cantCalculateFrameDelayReturnValue;
     }
 
-    if (previousFrameTimestamp < 0) {
+    if (previousFrameSystemTimestamp == 0) {
         SENTRY_LOG_DEBUG(@"Not calculating frames delay because no frames yet recorded.");
         return cantCalculateFrameDelayReturnValue;
     }
 
-    NSArray<SentryDelayedFrame *> *frames;
+    NSMutableArray<SentryDelayedFrame *> *frames;
     @synchronized(self.delayedFrames) {
         uint64_t oldestDelayedFrameStartTimestamp = UINT64_MAX;
         SentryDelayedFrame *oldestDelayedFrame = self.delayedFrames.firstObject;
@@ -135,17 +134,17 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp
         }
 
         // Copy as late as possible to avoid allocating unnecessary memory.
-        frames = self.delayedFrames.copy;
+        frames = self.delayedFrames.mutableCopy;
     }
 
-    // Check if there is an delayed frame going on but not recorded yet.
-    CFTimeInterval frameDuration = thisFrameTimestamp - previousFrameTimestamp;
-    CFTimeInterval ongoingDelayedFrame = 0.0;
-    if (frameDuration > slowFrameThreshold) {
-        ongoingDelayedFrame = frameDuration - slowFrameThreshold;
-    }
+    // Add a delayed frame for a potentially ongoing but not recorded delayed frame
+    SentryDelayedFrame *currentFrameDelay = [[SentryDelayedFrame alloc]
+        initWithStartTimestamp:previousFrameSystemTimestamp
+              expectedDuration:slowFrameThreshold
+                actualDuration:nanosecondsToTimeInterval(
+                                   endSystemTimestamp - previousFrameSystemTimestamp)];
 
-    CFTimeInterval delay = ongoingDelayedFrame;
+    [frames addObject:currentFrameDelay];
 
     // We need to calculate the intersections of the queried TimestampInterval
     // (startSystemTimestamp - endSystemTimestamp) with the recorded frame delays. Doing that
@@ -160,6 +159,8 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp
     NSDateInterval *queryDateInterval = [[NSDateInterval alloc] initWithStartDate:startDate
                                                                           endDate:endDate];
 
+    CFTimeInterval delay = 0.0;
+
     // Iterate in reverse order, as younger frame delays are more likely to match the queried
     // period.
     for (SentryDelayedFrame *frame in frames.reverseObjectEnumerator) {
@@ -170,23 +171,34 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp
             break;
         }
 
-        CFTimeInterval delayStartTime
-            = nanosecondsToTimeInterval(frame.startSystemTimestamp) + frame.expectedDuration;
-        NSDate *frameDelayStartDate =
-            [NSDate dateWithTimeIntervalSinceReferenceDate:delayStartTime];
+        delay = delay + [self calculateDelay:frame queryDateInterval:queryDateInterval];
+    }
 
-        NSDateInterval *frameDelayDateInterval = [[NSDateInterval alloc]
-            initWithStartDate:frameDelayStartDate
-                     duration:(frame.actualDuration - frame.expectedDuration)];
+    return delay;
+}
 
-        if ([queryDateInterval intersectsDateInterval:frameDelayDateInterval]) {
-            NSDateInterval *intersection =
-                [queryDateInterval intersectionWithDateInterval:frameDelayDateInterval];
-            delay = delay + intersection.duration;
-        }
+- (CFTimeInterval)calculateDelay:(SentryDelayedFrame *)delayedFrame
+               queryDateInterval:(NSDateInterval *)queryDateInterval
+{
+    CFTimeInterval delayStartTime = nanosecondsToTimeInterval(delayedFrame.startSystemTimestamp)
+        + delayedFrame.expectedDuration;
+    NSDate *frameDelayStartDate = [NSDate dateWithTimeIntervalSinceReferenceDate:delayStartTime];
+
+    NSTimeInterval duration = delayedFrame.actualDuration - delayedFrame.expectedDuration;
+    if (duration < 0) {
+        return 0.0;
     }
 
-    return delay;
+    NSDateInterval *frameDelayDateInterval =
+        [[NSDateInterval alloc] initWithStartDate:frameDelayStartDate duration:duration];
+
+    if ([queryDateInterval intersectsDateInterval:frameDelayDateInterval]) {
+        NSDateInterval *intersection =
+            [queryDateInterval intersectionWithDateInterval:frameDelayDateInterval];
+        return intersection.duration;
+    } else {
+        return 0.0;
+    }
 }
 
 @end

Sources/Sentry/SentryFramesTracker.m

@@ -240,8 +240,7 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp
     return [self.delayedFramesTracker getFramesDelay:startSystemTimestamp
                                   endSystemTimestamp:endSystemTimestamp
                                            isRunning:_isRunning
-                                  thisFrameTimestamp:self.displayLinkWrapper.timestamp
-                              previousFrameTimestamp:self.previousFrameTimestamp
+                        previousFrameSystemTimestamp:self.previousFrameSystemTimestamp
                                   slowFrameThreshold:slowFrameThreshold(_currentFrameRate)];
 }
 

Sources/Sentry/SentrySpan.m

@@ -35,6 +35,7 @@ @implementation SentrySpan {
     NSMutableDictionary<NSString *, id> *_tags;
     NSObject *_stateLock;
     BOOL _isFinished;
+    uint64_t _startSystemTime;
 #if SENTRY_HAS_UIKIT
     NSUInteger initTotalFrames;
     NSUInteger initSlowFrames;
@@ -49,6 +50,7 @@ - (instancetype)initWithContext:(SentrySpanContext *)context
 #endif // SENTRY_HAS_UIKIT
 {
     if (self = [super init]) {
+        _startSystemTime = SentryDependencyContainer.sharedInstance.dateProvider.systemTime;
         self.startTimestamp = [SentryDependencyContainer.sharedInstance.dateProvider date];
         _data = [[NSMutableDictionary alloc] init];
 
@@ -207,6 +209,14 @@ - (void)finishWithStatus:(SentrySpanStatus)status
 #if SENTRY_HAS_UIKIT
     if (_framesTracker.isRunning) {
 
+        CFTimeInterval framesDelay = [_framesTracker
+                getFramesDelay:_startSystemTime
+            endSystemTimestamp:SentryDependencyContainer.sharedInstance.dateProvider.systemTime];
+
+        if (framesDelay >= 0) {
+            [self setDataValue:@(framesDelay) forKey:@"frames.delay"];
+        }
+
         SentryScreenFrames *currentFrames = _framesTracker.currentFrames;
         NSInteger totalFrames = currentFrames.total - initTotalFrames;
         NSInteger slowFrames = currentFrames.slow - initSlowFrames;

Sources/Sentry/include/SentryDelayedFramesTracker.h

@@ -45,17 +45,15 @@ 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 thisFrameTimestamp The timestamp of the current frame.
- * @param previousFrameTimestamp The timestamp of the previous frame.
+ * @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
-              thisFrameTimestamp:(CFTimeInterval)thisFrameTimestamp
-          previousFrameTimestamp:(CFTimeInterval)previousFrameTimestamp
+    previousFrameSystemTimestamp:(uint64_t)previousFrameSystemTimestamp
               slowFrameThreshold:(CFTimeInterval)slowFrameThreshold;
 
 @end

Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift

@@ -310,7 +310,7 @@ class SentryFramesTrackerTests: XCTestCase {
 
         let startSystemTime = fixture.dateProvider.systemTime()
 
-        let delay = 0.5
+        let delay = 0.02
         fixture.dateProvider.advance(by: delay)
 
         let endSystemTime = fixture.dateProvider.systemTime()
@@ -321,6 +321,31 @@ class SentryFramesTrackerTests: XCTestCase {
         expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001))
     }
 
+    func testDelayedFrames_FrameIsDelayedSmallerThanSlowFrameThreshold_ReturnsDelay() {
+        fixture.dateProvider.advance(by: 2.0)
+
+        let sut = fixture.sut
+        sut.start()
+
+        let displayLink = fixture.displayLinkWrapper
+        displayLink.call()
+        displayLink.normalFrame()
+
+        fixture.dateProvider.advance(by: slowFrameThreshold(fixture.displayLinkWrapper.currentFrameRate.rawValue))
+
+        let startSystemTime = fixture.dateProvider.systemTime()
+
+        let delay = 0.0001
+        fixture.dateProvider.advance(by: delay)
+
+        let endSystemTime = fixture.dateProvider.systemTime()
+
+        let expectedDelay = delay
+
+        let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime)
+        expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001))
+    }
+
     private func testFrameDelay(timeIntervalAfterFrameStart: TimeInterval = 0.0, timeIntervalBeforeFrameEnd: TimeInterval = 0.0, expectedDelay: TimeInterval) {
         let sut = fixture.sut
         sut.start()

Tests/SentryTests/Transaction/SentrySpanTests.swift

@@ -499,30 +499,7 @@ class SentrySpanTests: XCTestCase {
         expect(sut.data["frames.frozen"]) == nil
     }
 
-    func testAddZeroSlowFrozenFrames_WhenSpanStartedBackgroundThread() {
-        let (displayLinkWrapper, framesTracker) = givenFramesTracker()
-
-        let expectation = expectation(description: "SpanStarted on a background thread")
-        DispatchQueue.global().async {
-            let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: framesTracker)
-
-            let slow = 2
-            let frozen = 1
-            let normal = 100
-            displayLinkWrapper.renderFrames(slow, frozen, normal)
-
-            sut.finish()
-
-            expect(sut.data["frames.total"] as? NSNumber) == NSNumber(value: slow + frozen + normal)
-            expect(sut.data["frames.slow"] as? NSNumber) == NSNumber(value: slow)
-            expect(sut.data["frames.frozen"] as? NSNumber) == NSNumber(value: frozen)
-            expectation.fulfill()
-        }
-
-        wait(for: [expectation], timeout: 1.0)
-    }
-
-    func testAddSlowFrozenFramesToData_WithPreexistingCounts() {
+    func testAddFrameStatisticsToData_WithPreexistingCounts() {
         let (displayLinkWrapper, framesTracker) = givenFramesTracker()
         let preexistingSlow = 1
         let preexistingFrozen = 2
@@ -531,16 +508,24 @@ class SentrySpanTests: XCTestCase {
 
         let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: framesTracker)
 
-        let slow = 7
-        let frozen = 8
-        let normal = 9
-        displayLinkWrapper.renderFrames(slow, frozen, normal)
+        let slowFrames = 1
+        let frozenFrames = 1
+        let normalFrames = 100
+        let totalFrames = slowFrames + frozenFrames + normalFrames
+        _ = displayLinkWrapper.slowestSlowFrame()
+        _ = displayLinkWrapper.fastestFrozenFrame()
+        displayLinkWrapper.renderFrames(0, 0, normalFrames)
 
         sut.finish()
 
-        expect(sut.data["frames.total"] as? NSNumber) == NSNumber(value: slow + frozen + normal)
-        expect(sut.data["frames.slow"] as? NSNumber) == NSNumber(value: slow)
-        expect(sut.data["frames.frozen"] as? NSNumber) == NSNumber(value: frozen)
+        expect(sut.data["frames.total"] as? NSNumber) == NSNumber(value: totalFrames)
+        expect(sut.data["frames.slow"] as? NSNumber) == NSNumber(value: slowFrames)
+        expect(sut.data["frames.frozen"] as? NSNumber) == NSNumber(value: frozenFrames)
+
+        let expectedFrameDuration = slowFrameThreshold(displayLinkWrapper.currentFrameRate.rawValue)
+        let expectedDelay = displayLinkWrapper.slowestSlowFrameDuration + displayLinkWrapper.fastestFrozenFrameDuration - expectedFrameDuration * 2 as NSNumber
+
+        expect(sut.data["frames.delay"] as? NSNumber).to(beCloseTo(expectedDelay, within: 0.0001))
     }
 
     func testNoFramesTracker_NoFramesAddedToData() {
@@ -551,11 +536,12 @@ class SentrySpanTests: XCTestCase {
         expect(sut.data["frames.total"]) == nil
         expect(sut.data["frames.slow"]) == nil
         expect(sut.data["frames.frozen"]) == nil
+        expect(sut.data["frames.delay"]) == nil
     }
 
     private func givenFramesTracker() -> (TestDisplayLinkWrapper, SentryFramesTracker) {
-        let displayLinkWrapper = TestDisplayLinkWrapper()
-        let framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: TestCurrentDateProvider(), keepDelayedFramesDuration: 0)
+        let displayLinkWrapper = TestDisplayLinkWrapper(dateProvider: self.fixture.currentDateProvider)
+        let framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: self.fixture.currentDateProvider, keepDelayedFramesDuration: 10)
         framesTracker.start()
         displayLinkWrapper.call()