From 36ad868fe3273f733b8517d874b1f01690be5f7a Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 14 Dec 2023 14:11:16 +0100 Subject: [PATCH] feat: Add frames delay to span data Also fix a couple of edge cases when calculating the frames delay when an ongoing delayed frame is not yet recorded. --- CHANGELOG.md | 2 +- Sources/Sentry/SentryDelayedFramesTracker.m | 70 ++++++++++++------- Sources/Sentry/SentryFramesTracker.m | 3 +- Sources/Sentry/SentrySpan.m | 10 +++ .../include/SentryDelayedFramesTracker.h | 6 +- .../SentryFramesTrackerTests.swift | 27 ++++++- .../Transaction/SentrySpanTests.swift | 52 +++++--------- 7 files changed, 104 insertions(+), 66 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 72cb1233a1b..9713cef5527 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,7 +4,7 @@ ## Features -- Add frames delay to transactions (#3487) +- Add frames delay to transactions and spans (#3487, #3495) - Add slow and frozen frames to spans (#3450, #3478) ## 8.17.1 diff --git a/Sources/Sentry/SentryDelayedFramesTracker.m b/Sources/Sentry/SentryDelayedFramesTracker.m index 0ef44cb59e8..a18dff36f68 100644 --- a/Sources/Sentry/SentryDelayedFramesTracker.m +++ b/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 *frames; + NSMutableArray *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,25 +171,44 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp break; } - CFTimeInterval delayStartTime - = nanosecondsToTimeInterval(frame.startSystemTimestamp) + frame.expectedDuration; - NSDate *frameDelayStartDate = - [NSDate dateWithTimeIntervalSinceReferenceDate:delayStartTime]; - - NSDateInterval *frameDelayDateInterval = [[NSDateInterval alloc] - initWithStartDate:frameDelayStartDate - duration:(frame.actualDuration - frame.expectedDuration)]; + delay = delay + [self calculateDelay:frame queryDateInterval:queryDateInterval]; + } - if ([queryDateInterval intersectsDateInterval:frameDelayDateInterval]) { - NSDateInterval *intersection = - [queryDateInterval intersectionWithDateInterval:frameDelayDateInterval]; - delay = delay + intersection.duration; - } + uint64_t queryTimeDuration = endSystemTimestamp - startSystemTimestamp; + if (queryTimeDuration < timeIntervalToNanoseconds(delay)) { + SENTRY_LOG_ERROR( + @"Not calculating frames delay because delay %f is longer than query time: %llu.", + delay, queryTimeDuration); + return cantCalculateFrameDelayReturnValue; } return delay; } +- (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; + } + + 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 NS_ASSUME_NONNULL_END diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index 06237d902af..dda690fd8ff 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/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)]; } diff --git a/Sources/Sentry/SentrySpan.m b/Sources/Sentry/SentrySpan.m index 8ea1cac2b50..7fd4b4971f5 100644 --- a/Sources/Sentry/SentrySpan.m +++ b/Sources/Sentry/SentrySpan.m @@ -35,6 +35,7 @@ @implementation SentrySpan { NSMutableDictionary *_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; diff --git a/Sources/Sentry/include/SentryDelayedFramesTracker.h b/Sources/Sentry/include/SentryDelayedFramesTracker.h index 7606e4bce23..f2c3527caeb 100644 --- a/Sources/Sentry/include/SentryDelayedFramesTracker.h +++ b/Sources/Sentry/include/SentryDelayedFramesTracker.h @@ -45,8 +45,7 @@ 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. @@ -54,8 +53,7 @@ SENTRY_NO_INIT - (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 diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index 042a33e2ed0..34acd569783 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/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() diff --git a/Tests/SentryTests/Transaction/SentrySpanTests.swift b/Tests/SentryTests/Transaction/SentrySpanTests.swift index b6e71b1d328..15b9ae320dd 100644 --- a/Tests/SentryTests/Transaction/SentrySpanTests.swift +++ b/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()