From e06f6c18afd817c52f49977ce63f0b717cfca6fe Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Mon, 27 Nov 2023 11:11:28 +0100 Subject: [PATCH 01/33] feat: Add slow and frozen frames to spans Add total, slow and frozen frame numbers to span data. Fixes GH-3448 --- CHANGELOG.md | 6 + Sources/Sentry/SentryBuildAppStartSpans.m | 2 +- Sources/Sentry/SentryFramesTracker.m | 10 ++ Sources/Sentry/SentrySpan.m | 56 ++++++++- Sources/Sentry/SentryTracer.m | 19 ++- Sources/Sentry/include/SentryFramesTracker.h | 3 + Sources/Sentry/include/SentrySpan.h | 17 ++- Tests/SentryTests/SentryClientTests.swift | 2 +- .../Transaction/SentrySpanTests.swift | 110 ++++++++++++++++-- 9 files changed, 205 insertions(+), 20 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index a379f1d4c78..e7d87451e81 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,11 @@ # Changelog +## Unreleased + +## Features + +- Add slow and frozen frames to spans (#3450) + ## 8.16.1 ### Features diff --git a/Sources/Sentry/SentryBuildAppStartSpans.m b/Sources/Sentry/SentryBuildAppStartSpans.m index 8477c72a970..bfa40a5280f 100644 --- a/Sources/Sentry/SentryBuildAppStartSpans.m +++ b/Sources/Sentry/SentryBuildAppStartSpans.m @@ -22,7 +22,7 @@ origin:SentryTraceOriginAutoAppStart sampled:tracer.sampled]; - return [[SentrySpan alloc] initWithTracer:tracer context:context]; + return [[SentrySpan alloc] initWithTracer:tracer context:context framesTracker:nil]; } NSArray * diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index d261c976cb7..37074cd2a86 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -242,4 +242,14 @@ - (void)dealloc @end +BOOL +sentryShouldAddSlowFrozenFramesData( + NSInteger totalFrames, NSInteger slowFrames, NSInteger frozenFrames) +{ + BOOL allBiggerThanZero = totalFrames >= 0 && slowFrames >= 0 && frozenFrames >= 0; + BOOL oneBiggerThanZero = totalFrames > 0 || slowFrames > 0 || frozenFrames > 0; + + return allBiggerThanZero && oneBiggerThanZero; +} + #endif // SENTRY_HAS_UIKIT diff --git a/Sources/Sentry/SentrySpan.m b/Sources/Sentry/SentrySpan.m index 95bbbcf5183..3caa32accaa 100644 --- a/Sources/Sentry/SentrySpan.m +++ b/Sources/Sentry/SentrySpan.m @@ -19,6 +19,11 @@ #import "SentryTraceHeader.h" #import "SentryTracer.h" +#if SENTRY_HAS_UIKIT +# import +# import +#endif // SENTRY_HAS_UIKIT + NS_ASSUME_NONNULL_BEGIN @interface @@ -30,9 +35,18 @@ @implementation SentrySpan { NSMutableDictionary *_tags; NSObject *_stateLock; BOOL _isFinished; +#if SENTRY_HAS_UIKIT + NSUInteger initTotalFrames; + NSUInteger initSlowFrames; + NSUInteger initFrozenFrames; + SentryFramesTracker *_framesTracker; +#endif // SENTRY_HAS_UIKIT } - (instancetype)initWithContext:(SentrySpanContext *)context +#if SENTRY_HAS_UIKIT + framesTracker:(nullable SentryFramesTracker *)framesTracker; +#endif // SENTRY_HAS_UIKIT { if (self = [super init]) { self.startTimestamp = [SentryDependencyContainer.sharedInstance.dateProvider date]; @@ -43,6 +57,17 @@ - (instancetype)initWithContext:(SentrySpanContext *)context if ([NSThread isMainThread]) { _data[SPAN_DATA_THREAD_NAME] = @"main"; + +#if SENTRY_HAS_UIKIT + // Only track frames if running on main thread. + _framesTracker = framesTracker; + if (_framesTracker.isRunning) { + SentryScreenFrames *currentFrames = _framesTracker.currentFrames; + initTotalFrames = currentFrames.total; + initSlowFrames = currentFrames.slow; + initFrozenFrames = currentFrames.frozen; + } +#endif // SENTRY_HAS_UIKIT } else { _data[SPAN_DATA_THREAD_NAME] = [SentryDependencyContainer.sharedInstance.threadInspector getThreadName:currentThread]; @@ -64,9 +89,17 @@ - (instancetype)initWithContext:(SentrySpanContext *)context return self; } -- (instancetype)initWithTracer:(SentryTracer *)tracer context:(SentrySpanContext *)context +- (instancetype)initWithTracer:(SentryTracer *)tracer + context:(SentrySpanContext *)context +#if SENTRY_HAS_UIKIT + framesTracker:(nullable SentryFramesTracker *)framesTracker +{ + if (self = [self initWithContext:context framesTracker:framesTracker]) { +#else { if (self = [self initWithContext:context]) { +#endif // SENTRY_HAS_UIKIT + _tracer = tracer; } return self; @@ -171,6 +204,27 @@ - (void)finishWithStatus:(SentrySpanStatus)status SENTRY_LOG_DEBUG(@"Setting span timestamp: %@ at system time %llu", self.timestamp, (unsigned long long)SentryDependencyContainer.sharedInstance.dateProvider.systemTime); } + +#if SENTRY_HAS_UIKIT + if (_framesTracker.isRunning) { + + SentryScreenFrames *currentFrames = _framesTracker.currentFrames; + NSInteger totalFrames = currentFrames.total - initTotalFrames; + NSInteger slowFrames = currentFrames.slow - initSlowFrames; + NSInteger frozenFrames = currentFrames.frozen - initFrozenFrames; + + if (sentryShouldAddSlowFrozenFramesData(totalFrames, slowFrames, frozenFrames)) { + [self setDataValue:@(totalFrames) forKey:@"frames.total"]; + [self setDataValue:@(slowFrames) forKey:@"frames.slow"]; + [self setDataValue:@(frozenFrames) forKey:@"frames.frozen"]; + + SENTRY_LOG_DEBUG(@"Frames for span \"%@\" Total:%ld Slow:%ld Frozen:%ld", + self.operation, (long)totalFrames, (long)slowFrames, (long)frozenFrames); + } + } + +#endif // SENTRY_HAS_UIKIT + if (self.tracer == nil) { SENTRY_LOG_DEBUG( @"No tracer associated with span with id %@", self.spanId.sentrySpanIdString); diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 04f21900122..39284809123 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -123,7 +123,11 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti hub:(nullable SentryHub *)hub configuration:(SentryTracerConfiguration *)configuration; { - if (!(self = [super initWithContext:transactionContext])) { + if (!(self = [super initWithContext:transactionContext +#if SENTRY_HAS_UIKIT + framesTracker:SentryDependencyContainer.sharedInstance.framesTracker +#endif // SENTRY_HAS_UIKIT + ])) { return nil; } @@ -351,7 +355,13 @@ - (void)cancelDeadlineTimer spanDescription:description sampled:self.sampled]; - SentrySpan *child = [[SentrySpan alloc] initWithTracer:self context:context]; + SentrySpan *child = + [[SentrySpan alloc] initWithTracer:self + context:context +#if SENTRY_HAS_UIKIT + framesTracker:SentryDependencyContainer.sharedInstance.framesTracker +#endif // SENTRY_HAS_UIKIT + ]; child.startTimestamp = [SentryDependencyContainer.sharedInstance.dateProvider date]; SENTRY_LOG_DEBUG(@"Started child span %@ under %@", child.spanId.sentrySpanIdString, parentId.sentrySpanIdString); @@ -741,10 +751,7 @@ - (void)addMeasurements:(SentryTransaction *)transaction NSInteger slowFrames = currentFrames.slow - initSlowFrames; NSInteger frozenFrames = currentFrames.frozen - initFrozenFrames; - BOOL allBiggerThanZero = totalFrames >= 0 && slowFrames >= 0 && frozenFrames >= 0; - BOOL oneBiggerThanZero = totalFrames > 0 || slowFrames > 0 || frozenFrames > 0; - - if (allBiggerThanZero && oneBiggerThanZero) { + if (sentryShouldAddSlowFrozenFramesData(totalFrames, slowFrames, frozenFrames)) { [self setMeasurement:@"frames_total" value:@(totalFrames)]; [self setMeasurement:@"frames_slow" value:@(slowFrames)]; [self setMeasurement:@"frames_frozen" value:@(frozenFrames)]; diff --git a/Sources/Sentry/include/SentryFramesTracker.h b/Sources/Sentry/include/SentryFramesTracker.h index 6724c3562c6..22e5c86e3b5 100644 --- a/Sources/Sentry/include/SentryFramesTracker.h +++ b/Sources/Sentry/include/SentryFramesTracker.h @@ -40,6 +40,9 @@ NS_ASSUME_NONNULL_BEGIN @end +BOOL sentryShouldAddSlowFrozenFramesData( + NSInteger totalFrames, NSInteger slowFrames, NSInteger frozenFrames); + NS_ASSUME_NONNULL_END #endif // SENTRY_HAS_UIKIT diff --git a/Sources/Sentry/include/SentrySpan.h b/Sources/Sentry/include/SentrySpan.h index 72ddce92044..70678b7d67e 100644 --- a/Sources/Sentry/include/SentrySpan.h +++ b/Sources/Sentry/include/SentrySpan.h @@ -6,6 +6,10 @@ NS_ASSUME_NONNULL_BEGIN @class SentryTracer, SentryId, SentrySpanId, SentryFrame, SentrySpanContext; @protocol SentrySerializable; +#if SENTRY_HAS_UIKIT +@class SentryFramesTracker; +#endif // SENTRY_HAS_UIKIT + @interface SentrySpan : NSObject SENTRY_NO_INIT @@ -85,13 +89,22 @@ SENTRY_NO_INIT * @param transaction The @c SentryTracer managing the transaction this span is associated with. * @param context This span context information. */ -- (instancetype)initWithTracer:(SentryTracer *)transaction context:(SentrySpanContext *)context; +- (instancetype)initWithTracer:(SentryTracer *)transaction + context:(SentrySpanContext *)context +#if SENTRY_HAS_UIKIT + framesTracker:(nullable SentryFramesTracker *)framesTracker; +#endif // SENTRY_HAS_UIKIT +; /** * Init a @c SentrySpan with given context. * @param context This span context information. */ -- (instancetype)initWithContext:(SentrySpanContext *)context; +- (instancetype)initWithContext:(SentrySpanContext *)context +#if SENTRY_HAS_UIKIT + framesTracker:(nullable SentryFramesTracker *)framesTracker; +#endif // SENTRY_HAS_UIKIT +; - (void)setExtraValue:(nullable id)value forKey:(NSString *)key DEPRECATED_ATTRIBUTE; @end diff --git a/Tests/SentryTests/SentryClientTests.swift b/Tests/SentryTests/SentryClientTests.swift index 43e06071e02..a1648cbaa05 100644 --- a/Tests/SentryTests/SentryClientTests.swift +++ b/Tests/SentryTests/SentryClientTests.swift @@ -348,7 +348,7 @@ class SentryClientTest: XCTestCase { func testCaptureTransactionWithoutScreen() { SentryDependencyContainer.sharedInstance().application = TestSentryUIApplication() - let event = Transaction(trace: SentryTracer(context: SpanContext(operation: "test")), children: []) + let event = Transaction(trace: SentryTracer(context: SpanContext(operation: "test"), framesTracker: nil), children: []) fixture.getSut().capture(event: event, scope: fixture.scope) try? assertLastSentEventWithAttachment { event in diff --git a/Tests/SentryTests/Transaction/SentrySpanTests.swift b/Tests/SentryTests/Transaction/SentrySpanTests.swift index 4001f82890a..2efaf90a47d 100644 --- a/Tests/SentryTests/Transaction/SentrySpanTests.swift +++ b/Tests/SentryTests/Transaction/SentrySpanTests.swift @@ -1,3 +1,4 @@ +import Nimble import Sentry import SentryTestUtils import XCTest @@ -14,7 +15,11 @@ class SentrySpanTests: XCTestCase { let extraValue = "extra_value" let options: Options let currentDateProvider = TestCurrentDateProvider() +#if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) + let tracer = SentryTracer(context: SpanContext(operation: "TEST"), framesTracker: nil) + #else let tracer = SentryTracer(context: SpanContext(operation: "TEST")) + #endif init() { options = Options() @@ -33,6 +38,13 @@ class SentrySpanTests: XCTestCase { return hub.startTransaction(name: someTransaction, operation: someOperation) } + func getSutWithTracer() -> SentrySpan { +#if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) + return SentrySpan(tracer: tracer, context: SpanContext(operation: someOperation, sampled: .undecided), framesTracker: nil) +#else + return SentrySpan(tracer: tracer, context: SpanContext(operation: someOperation, sampled: .undecided)) +#endif + } } override func setUp() { @@ -142,7 +154,7 @@ class SentrySpanTests: XCTestCase { } func testFinishSpanWithDefaultTimestamp() { - let span = SentrySpan(tracer: fixture.tracer, context: SpanContext(operation: fixture.someOperation, sampled: .undecided)) + let span = fixture.getSutWithTracer() span.finish() XCTAssertEqual(span.startTimestamp, TestData.timestamp) @@ -152,7 +164,7 @@ class SentrySpanTests: XCTestCase { } func testFinishSpanWithCustomTimestamp() { - let span = SentrySpan(tracer: fixture.tracer, context: SpanContext(operation: fixture.someOperation, sampled: .undecided)) + let span = fixture.getSutWithTracer() span.timestamp = Date(timeIntervalSince1970: 123) span.finish() @@ -292,15 +304,15 @@ class SentrySpanTests: XCTestCase { XCTAssertEqual("manual", serialization["origin"] as? String) } - func testSerialization_NoFrames() { - let span = SentrySpan(tracer: fixture.tracer, context: SpanContext(operation: "test")) + func testSerialization_NoStacktraceFrames() { + let span = fixture.getSutWithTracer() let serialization = span.serialize() XCTAssertEqual(2, (serialization["data"] as? [String: Any])?.count, "Only expected thread.name and thread.id in data.") } - func testSerialization_withFrames() { - let span = SentrySpan(tracer: fixture.tracer, context: SpanContext(operation: "test")) + func testSerialization_withStacktraceFrames() { + let span = fixture.getSutWithTracer() span.frames = [TestData.mainFrame, TestData.testFrame] let serialization = span.serialize() @@ -324,7 +336,7 @@ class SentrySpanTests: XCTestCase { } func testSanitizeDataSpan() { - let span = SentrySpan(tracer: fixture.tracer, context: SpanContext(operation: fixture.someOperation, sampled: .undecided)) + let span = fixture.getSutWithTracer() span.setData(value: Date(timeIntervalSince1970: 10), key: "date") span.finish() @@ -365,7 +377,7 @@ class SentrySpanTests: XCTestCase { } func testTraceHeaderUndecided() { - let span = SentrySpan(tracer: fixture.tracer, context: SpanContext(operation: fixture.someOperation, sampled: .undecided)) + let span = fixture.getSutWithTracer() let header = span.toTraceHeader() XCTAssertEqual(header.traceId, span.traceId) @@ -376,7 +388,7 @@ class SentrySpanTests: XCTestCase { @available(*, deprecated) func testSetExtra_ForwardsToSetData() { - let sut = SentrySpan(tracer: fixture.tracer, context: SpanContext(operation: "test")) + let sut = fixture.getSutWithTracer() sut.setExtra(value: 0, key: "key") let data = sut.data as [String: Any] @@ -387,8 +399,13 @@ class SentrySpanTests: XCTestCase { // Span has a weak reference to tracer. If we don't keep a reference // to the tracer ARC will deallocate the tracer. let sutGenerator: () -> Span = { +#if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) + let tracer = SentryTracer(context: SpanContext(operation: "TEST"), framesTracker: nil) + return SentrySpan(tracer: tracer, context: SpanContext(operation: ""), framesTracker: nil) + #else let tracer = SentryTracer(context: SpanContext(operation: "TEST")) return SentrySpan(tracer: tracer, context: SpanContext(operation: "")) + #endif } let sut = sutGenerator() @@ -451,4 +468,79 @@ class SentrySpanTests: XCTestCase { XCTAssertEqual(nameForSentrySpanStatus(.outOfRange), kSentrySpanStatusNameOutOfRange) XCTAssertEqual(nameForSentrySpanStatus(.dataLoss), kSentrySpanStatusNameDataLoss) } + +#if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) + func testAddSlowFrozenFramesToData() { + let (displayLinkWrapper, framesTracker) = givenFramesTracker() + + let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: framesTracker) + + let slow = 2 + let frozen = 1 + let normal = 100 + displayLinkWrapper.givenFrames(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) + } + + func testDontAddAllZeroSlowFrozenFramesToData() { + let (_, framesTracker) = givenFramesTracker() + + let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: framesTracker) + + sut.finish() + + expect(sut.data["frames.total"]) == nil + expect(sut.data["frames.slow"]) == nil + expect(sut.data["frames.frozen"]) == nil + } + + func testDontAddZeroSlowFrozenFrames_WhenSpanStartedBackgroundThread() { + let (displayLinkWrapper, framesTracker) = givenFramesTracker() + + let dispatchGroup = DispatchGroup() + dispatchGroup.enter() + DispatchQueue.global().async { + let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: framesTracker) + + let slow = 2 + let frozen = 1 + let normal = 100 + displayLinkWrapper.givenFrames(slow, frozen, normal) + + sut.finish() + + expect(sut.data["frames.total"]) == nil + expect(sut.data["frames.slow"]) == nil + expect(sut.data["frames.frozen"]) == nil + + dispatchGroup.leave() + } + + dispatchGroup.wait() + } + + func testNoFramesTracker_NoFramesAddedToData() { + let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: nil) + + sut.finish() + + expect(sut.data["frames.total"]) == nil + expect(sut.data["frames.slow"]) == nil + expect(sut.data["frames.frozen"]) == nil + } + + private func givenFramesTracker() -> (TestDisplayLinkWrapper, SentryFramesTracker) { + let displayLinkWrapper = TestDisplayLinkWrapper() + let framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper) + framesTracker.start() + displayLinkWrapper.call() + + return (displayLinkWrapper, framesTracker) + } +#endif } From 96479bb56e444161fee53b5e889c27b34f00b337 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Wed, 29 Nov 2023 10:00:55 +0100 Subject: [PATCH 02/33] Update Tests/SentryTests/Transaction/SentrySpanTests.swift Co-authored-by: Andrew McKnight --- Tests/SentryTests/Transaction/SentrySpanTests.swift | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/Tests/SentryTests/Transaction/SentrySpanTests.swift b/Tests/SentryTests/Transaction/SentrySpanTests.swift index 2efaf90a47d..8cb984b1083 100644 --- a/Tests/SentryTests/Transaction/SentrySpanTests.swift +++ b/Tests/SentryTests/Transaction/SentrySpanTests.swift @@ -402,10 +402,10 @@ class SentrySpanTests: XCTestCase { #if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) let tracer = SentryTracer(context: SpanContext(operation: "TEST"), framesTracker: nil) return SentrySpan(tracer: tracer, context: SpanContext(operation: ""), framesTracker: nil) - #else +#else let tracer = SentryTracer(context: SpanContext(operation: "TEST")) return SentrySpan(tracer: tracer, context: SpanContext(operation: "")) - #endif +#endif } let sut = sutGenerator() From e6b84909b5cd4b6c36a7efb9a8f08ea6d696c996 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Wed, 29 Nov 2023 10:01:09 +0100 Subject: [PATCH 03/33] Update Tests/SentryTests/Transaction/SentrySpanTests.swift Co-authored-by: Andrew McKnight --- Tests/SentryTests/Transaction/SentrySpanTests.swift | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/Tests/SentryTests/Transaction/SentrySpanTests.swift b/Tests/SentryTests/Transaction/SentrySpanTests.swift index 8cb984b1083..2d5e324ff9d 100644 --- a/Tests/SentryTests/Transaction/SentrySpanTests.swift +++ b/Tests/SentryTests/Transaction/SentrySpanTests.swift @@ -17,9 +17,9 @@ class SentrySpanTests: XCTestCase { let currentDateProvider = TestCurrentDateProvider() #if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) let tracer = SentryTracer(context: SpanContext(operation: "TEST"), framesTracker: nil) - #else +#else let tracer = SentryTracer(context: SpanContext(operation: "TEST")) - #endif +#endif init() { options = Options() From 6e6b8915f4aa8460bcf7cd436378df2c2d1518cb Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Wed, 29 Nov 2023 10:01:39 +0100 Subject: [PATCH 04/33] code review --- SentryTestUtils/TestDisplayLinkWrapper.swift | 2 +- Tests/SentryTests/PrivateSentrySDKOnlyTests.swift | 2 +- Tests/SentryTests/Transaction/SentrySpanTests.swift | 4 ++-- Tests/SentryTests/Transaction/SentryTracerTests.swift | 6 +++--- 4 files changed, 7 insertions(+), 7 deletions(-) diff --git a/SentryTestUtils/TestDisplayLinkWrapper.swift b/SentryTestUtils/TestDisplayLinkWrapper.swift index d3ef04e408a..9db29f7dbcd 100644 --- a/SentryTestUtils/TestDisplayLinkWrapper.swift +++ b/SentryTestUtils/TestDisplayLinkWrapper.swift @@ -99,7 +99,7 @@ public class TestDisplayLinkWrapper: SentryDisplayLinkWrapper { call() } - public func givenFrames(_ slow: Int, _ frozen: Int, _ normal: Int) { + public func renderFrames(_ slow: Int, _ frozen: Int, _ normal: Int) { self.call() for _ in 0.. Date: Wed, 29 Nov 2023 10:03:55 +0100 Subject: [PATCH 05/33] use test expectation --- Tests/SentryTests/Transaction/SentrySpanTests.swift | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/Tests/SentryTests/Transaction/SentrySpanTests.swift b/Tests/SentryTests/Transaction/SentrySpanTests.swift index 93ce445ce1b..cff2f38a5a2 100644 --- a/Tests/SentryTests/Transaction/SentrySpanTests.swift +++ b/Tests/SentryTests/Transaction/SentrySpanTests.swift @@ -502,8 +502,7 @@ class SentrySpanTests: XCTestCase { func testDontAddZeroSlowFrozenFrames_WhenSpanStartedBackgroundThread() { let (displayLinkWrapper, framesTracker) = givenFramesTracker() - let dispatchGroup = DispatchGroup() - dispatchGroup.enter() + let expectation = expectation(description: "SpanStarted on a background thread") DispatchQueue.global().async { let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: framesTracker) @@ -518,10 +517,10 @@ class SentrySpanTests: XCTestCase { expect(sut.data["frames.slow"]) == nil expect(sut.data["frames.frozen"]) == nil - dispatchGroup.leave() + expectation.fulfill() } - dispatchGroup.wait() + wait(for: [expectation], timeout: 1.0) } func testNoFramesTracker_NoFramesAddedToData() { From cd0e0d2843cfe030496a7df87680894612bde39f Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Wed, 29 Nov 2023 10:06:01 +0100 Subject: [PATCH 06/33] add extra test case --- .../Transaction/SentrySpanTests.swift | 21 +++++++++++++++++++ 1 file changed, 21 insertions(+) diff --git a/Tests/SentryTests/Transaction/SentrySpanTests.swift b/Tests/SentryTests/Transaction/SentrySpanTests.swift index cff2f38a5a2..99c7981342d 100644 --- a/Tests/SentryTests/Transaction/SentrySpanTests.swift +++ b/Tests/SentryTests/Transaction/SentrySpanTests.swift @@ -523,6 +523,27 @@ class SentrySpanTests: XCTestCase { wait(for: [expectation], timeout: 1.0) } + func testAddSlowFrozenFramesToData_WithPreexistingCounts() { + let (displayLinkWrapper, framesTracker) = givenFramesTracker() + let preexistingSlow = 1 + let preexistingFrozen = 2 + let preexistingNormal = 3 + displayLinkWrapper.renderFrames(preexistingSlow, preexistingFrozen, preexistingNormal) + + let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: framesTracker) + + let slow = 7 + let frozen = 8 + let normal = 9 + 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) + } + func testNoFramesTracker_NoFramesAddedToData() { let sut = SentrySpan(context: SpanContext(operation: "TEST"), framesTracker: nil) From e216aadab45cb7275ee671fca9e654527dd59c98 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 30 Nov 2023 12:26:52 +0100 Subject: [PATCH 07/33] backup --- Samples/iOS-Swift/iOS-Swift/AppDelegate.swift | 2 +- SentryTestUtils/TestDisplayLinkWrapper.swift | 6 +- Sources/Sentry/SentryDependencyContainer.m | 3 +- Sources/Sentry/SentryFramesTracker.m | 146 +++++++++++- Sources/Sentry/SentryTime.mm | 7 + Sources/Sentry/SentryTracer.m | 15 +- Sources/Sentry/include/SentryFramesTracker.h | 7 +- Sources/Sentry/include/SentryTime.h | 2 + .../SentryFramesTrackerTests.swift | 209 +++++++++++++++++- 9 files changed, 376 insertions(+), 21 deletions(-) diff --git a/Samples/iOS-Swift/iOS-Swift/AppDelegate.swift b/Samples/iOS-Swift/iOS-Swift/AppDelegate.swift index c355508fdc6..d64512a7119 100644 --- a/Samples/iOS-Swift/iOS-Swift/AppDelegate.swift +++ b/Samples/iOS-Swift/iOS-Swift/AppDelegate.swift @@ -66,7 +66,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate { scope.setTag(value: "swift", key: "language") let user = User(userId: "1") - user.email = "tony@example.com" + user.email = "philipp@example.com" scope.setUser(user) if let path = Bundle.main.path(forResource: "Tongariro", ofType: "jpg") { diff --git a/SentryTestUtils/TestDisplayLinkWrapper.swift b/SentryTestUtils/TestDisplayLinkWrapper.swift index 9db29f7dbcd..687c8bbb421 100644 --- a/SentryTestUtils/TestDisplayLinkWrapper.swift +++ b/SentryTestUtils/TestDisplayLinkWrapper.swift @@ -1,8 +1,6 @@ import Foundation #if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) -/// The smallest magnitude of time that is significant to how frames are classified as normal/slow/frozen. -let timeEpsilon = 0.001 public enum GPUFrame { case normal @@ -23,8 +21,10 @@ public class TestDisplayLinkWrapper: SentryDisplayLinkWrapper { public var target: AnyObject! public var selector: Selector! public var currentFrameRate: FrameRate = .low - let frozenFrameThreshold = 0.7 + public let frozenFrameThreshold = 0.7 public var dateProvider: TestCurrentDateProvider + /// The smallest magnitude of time that is significant to how frames are classified as normal/slow/frozen. + public let timeEpsilon = 0.001 public init(dateProvider: TestCurrentDateProvider = TestCurrentDateProvider()) { self.dateProvider = dateProvider diff --git a/Sources/Sentry/SentryDependencyContainer.m b/Sources/Sentry/SentryDependencyContainer.m index dd04aaa1ff6..ed8b36dc3d8 100644 --- a/Sources/Sentry/SentryDependencyContainer.m +++ b/Sources/Sentry/SentryDependencyContainer.m @@ -268,7 +268,8 @@ - (SentryFramesTracker *)framesTracker @synchronized(sentryDependencyContainerLock) { if (_framesTracker == nil) { _framesTracker = [[SentryFramesTracker alloc] - initWithDisplayLinkWrapper:[[SentryDisplayLinkWrapper alloc] init]]; + initWithDisplayLinkWrapper:[[SentryDisplayLinkWrapper alloc] init] + dateProvider:self.dateProvider]; } } } diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index 37074cd2a86..9e85f1f05e7 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -4,7 +4,6 @@ # import "SentryCompiler.h" # import "SentryCurrentDateProvider.h" -# import "SentryDependencyContainer.h" # import "SentryDisplayLinkWrapper.h" # import "SentryLog.h" # import "SentryProfiler.h" @@ -21,11 +20,42 @@ static CFTimeInterval const SentryFrozenFrameThreshold = 0.7; static CFTimeInterval const SentryPreviousFrameInitialValue = -1; +static NSInteger const SentryDelayedFramesCapacity = 1024; + +@interface SentryDelayedFrame : NSObject +SENTRY_NO_INIT + +- (instancetype)initWithStartTimestamp:(uint64_t)startSystemTimestamp + expectedDuration:(CFTimeInterval)expectedDuration + actualDuration:(CFTimeInterval)actualDuration; + +@property (nonatomic, readonly) uint64_t startSystemTimestamp; +@property (nonatomic, readonly) CFTimeInterval expectedDuration; +@property (nonatomic, readonly) CFTimeInterval actualDuration; + +@end + +@implementation SentryDelayedFrame + +- (instancetype)initWithStartTimestamp:(uint64_t)startSystemTimestamp + expectedDuration:(CFTimeInterval)expectedDuration + actualDuration:(CFTimeInterval)actualDuration +{ + if (self = [super init]) { + _startSystemTimestamp = startSystemTimestamp; + _expectedDuration = expectedDuration; + _actualDuration = actualDuration; + } + return self; +} + +@end @interface SentryFramesTracker () @property (nonatomic, strong, readonly) SentryDisplayLinkWrapper *displayLinkWrapper; +@property (nonatomic, strong, readonly) SentryCurrentDateProvider *dateProvider; @property (nonatomic, assign) CFTimeInterval previousFrameTimestamp; @property (nonatomic) uint64_t previousFrameSystemTimestamp; @property (nonatomic, strong) NSHashTable> *listeners; @@ -35,6 +65,12 @@ @property (nonatomic, readwrite) SentryMutableFrameInfoTimeSeries *frameRateTimestamps; # endif // SENTRY_TARGET_PROFILING_SUPPORTED +/** + * The delayed frames are stored as a ring buffer to minimize memory footprint. + */ +@property (nonatomic, strong) NSMutableArray *delayedFrames; +@property (nonatomic) uint8_t delayedFrameWriteIndex; + @end CFTimeInterval @@ -52,11 +88,15 @@ @implementation SentryFramesTracker { } - (instancetype)initWithDisplayLinkWrapper:(SentryDisplayLinkWrapper *)displayLinkWrapper + dateProvider:(SentryCurrentDateProvider *)dateProvider; { if (self = [super init]) { _isRunning = NO; _displayLinkWrapper = displayLinkWrapper; + _dateProvider = dateProvider; _listeners = [NSHashTable weakObjectsHashTable]; + _delayedFrames = [[NSMutableArray alloc] initWithCapacity:SentryDelayedFramesCapacity]; + _delayedFrameWriteIndex = 0; [self resetFrames]; SENTRY_LOG_DEBUG(@"Initialized frame tracker %@", self); } @@ -105,8 +145,7 @@ - (void)start - (void)displayLinkCallback { CFTimeInterval thisFrameTimestamp = self.displayLinkWrapper.timestamp; - uint64_t thisFrameSystemTimestamp - = SentryDependencyContainer.sharedInstance.dateProvider.systemTime; + uint64_t thisFrameSystemTimestamp = self.dateProvider.systemTime; if (self.previousFrameTimestamp == SentryPreviousFrameInitialValue) { self.previousFrameTimestamp = thisFrameTimestamp; @@ -167,6 +206,13 @@ - (void)displayLinkCallback array:self.frozenFrameTimestamps]; # endif // SENTRY_TARGET_PROFILING_SUPPORTED } + + if (frameDuration > slowFrameThreshold(currentFrameRate)) { + [self recordDelayedFrame:self.previousFrameSystemTimestamp + expectedDuration:slowFrameThreshold(currentFrameRate) + actualDuration:frameDuration]; + } + _totalFrames++; self.previousFrameTimestamp = thisFrameTimestamp; self.previousFrameSystemTimestamp = thisFrameSystemTimestamp; @@ -214,6 +260,100 @@ - (SentryScreenFrames *)currentFrames # endif // SENTRY_TARGET_PROFILING_SUPPORTED } +- (void)recordDelayedFrame:(uint64_t)startSystemTimestamp + expectedDuration:(CFTimeInterval)expectedDuration + actualDuration:(CFTimeInterval)actualDuration +{ + @synchronized(self.delayedFrames) { + SENTRY_LOG_DEBUG(@"FrameDelay: Record expected:%f ms actual %f ms", expectedDuration * 1000, + actualDuration * 1000); + SentryDelayedFrame *delayedFrame = + [[SentryDelayedFrame alloc] initWithStartTimestamp:startSystemTimestamp + expectedDuration:expectedDuration + actualDuration:actualDuration]; + if (self.delayedFrames.count < SentryDelayedFramesCapacity) { + [self.delayedFrames addObject:delayedFrame]; + } else { + self.delayedFrames[self.delayedFrameWriteIndex] = delayedFrame; + } + + self.delayedFrameWriteIndex + = (self.delayedFrameWriteIndex + 1) % SentryDelayedFramesCapacity; + } +} + +- (CFTimeInterval)getFrameDelay:(uint64_t)startSystemTimestamp + endSystemTimestamp:(uint64_t)endSystemTimestamp +{ + CFTimeInterval delay = 0.0; + + if (startSystemTimestamp >= endSystemTimestamp) { + return delay; + } + + @synchronized(self.delayedFrames) { + + // Although we use a ring buffer, and it could take a while until we get to frames within + // the time interval for which we want to return frame delay, we don't want to use a normal + // for loop with accessing the elements by index because NSFastEnumeration is faster than a + // normal for loop and in the worst case we need to iterate over all elements anyways. A + // binary search to find the first and last delayed frame in our time interval doesn't help + // either because, again, we need to iterate over all elements in the worst case. + + uint64_t oldestDelayedFrameStartTimestamp = UINT64_MAX; + uint64_t newestDelayedFrameEndTimestamp = 0; + + for (SentryDelayedFrame *frame in self.delayedFrames) { + if (frame.startSystemTimestamp < oldestDelayedFrameStartTimestamp) { + oldestDelayedFrameStartTimestamp = frame.startSystemTimestamp; + } + + uint64_t frameEndSystemTimeStamp + = frame.startSystemTimestamp + timeIntervalToNanoseconds(frame.actualDuration); + if (frame.startSystemTimestamp < newestDelayedFrameEndTimestamp) { + newestDelayedFrameEndTimestamp = frameEndSystemTimeStamp; + } + } + + if (oldestDelayedFrameStartTimestamp > startSystemTimestamp) { + return -1.0; + } + + if (newestDelayedFrameEndTimestamp < endSystemTimestamp) { + return -1.0; + } + + for (SentryDelayedFrame *frame in self.delayedFrames) { + NSDate *startDate = + [NSDate dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval( + startSystemTimestamp)]; + NSDate *endDate = + [NSDate dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval( + endSystemTimestamp)]; + + CFTimeInterval delayStartTime + = nanosecondsToTimeInterval(frame.startSystemTimestamp) + frame.expectedDuration; + NSDate *frameDelayStartDate = + [NSDate dateWithTimeIntervalSinceReferenceDate:delayStartTime]; + + NSDateInterval *frameDelayDateInterval = + [[NSDateInterval alloc] initWithStartDate:startDate endDate:endDate]; + + // Only use the date interval for the actual delay + NSDateInterval *frameDateInterval = [[NSDateInterval alloc] + initWithStartDate:frameDelayStartDate + duration:(frame.actualDuration - frame.expectedDuration)]; + + if ([frameDelayDateInterval intersectsDateInterval:frameDateInterval]) { + NSDateInterval *intersection = + [frameDelayDateInterval intersectionWithDateInterval:frameDateInterval]; + delay = delay + intersection.duration; + } + } + } + return delay; +} + - (void)addListener:(id)listener { diff --git a/Sources/Sentry/SentryTime.mm b/Sources/Sentry/SentryTime.mm index 91da1b3e71b..7e9c867c476 100644 --- a/Sources/Sentry/SentryTime.mm +++ b/Sources/Sentry/SentryTime.mm @@ -15,6 +15,13 @@ return (uint64_t)(seconds * 1e9); } +double +nanosecondsToTimeInterval(uint64_t nanoseconds) +{ + NSCAssert(nanoseconds <= UINT64_MAX, @"Nanoseconds must not exceed UINT64_MAX"); + return (double)nanoseconds / 1e9; +} + uint64_t getAbsoluteTime(void) { diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 39284809123..634394b17a3 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -751,13 +751,22 @@ - (void)addMeasurements:(SentryTransaction *)transaction NSInteger slowFrames = currentFrames.slow - initSlowFrames; NSInteger frozenFrames = currentFrames.frozen - initFrozenFrames; + CFTimeInterval frameDelay = [framesTracker + getFrameDelay:self.startSystemTime + endSystemTimestamp:SentryDependencyContainer.sharedInstance.dateProvider.systemTime]; + if (sentryShouldAddSlowFrozenFramesData(totalFrames, slowFrames, frozenFrames)) { [self setMeasurement:@"frames_total" value:@(totalFrames)]; [self setMeasurement:@"frames_slow" value:@(slowFrames)]; [self setMeasurement:@"frames_frozen" value:@(frozenFrames)]; - - SENTRY_LOG_DEBUG(@"Frames for transaction \"%@\" Total:%ld Slow:%ld Frozen:%ld", - self.operation, (long)totalFrames, (long)slowFrames, (long)frozenFrames); + [self setMeasurement:@"frames_delay" + value:@(frameDelay) + unit:SentryMeasurementUnitDuration.second]; + + SENTRY_LOG_DEBUG(@"FrameDelay: Frames for transaction \"%@\" Total:%ld Slow:%ld " + @"Frozen:%ld delay:%f ms", + self.operation, (long)totalFrames, (long)slowFrames, (long)frozenFrames, + frameDelay * 1000); } } } diff --git a/Sources/Sentry/include/SentryFramesTracker.h b/Sources/Sentry/include/SentryFramesTracker.h index 22e5c86e3b5..b3a1f799408 100644 --- a/Sources/Sentry/include/SentryFramesTracker.h +++ b/Sources/Sentry/include/SentryFramesTracker.h @@ -5,6 +5,7 @@ # import "SentryProfilingConditionals.h" @class SentryOptions, SentryDisplayLinkWrapper, SentryScreenFrames; +@class SentryCurrentDateProvider; NS_ASSUME_NONNULL_BEGIN @@ -21,7 +22,8 @@ NS_ASSUME_NONNULL_BEGIN */ @interface SentryFramesTracker : NSObject -- (instancetype)initWithDisplayLinkWrapper:(SentryDisplayLinkWrapper *)displayLinkWrapper; +- (instancetype)initWithDisplayLinkWrapper:(SentryDisplayLinkWrapper *)displayLinkWrapper + dateProvider:(SentryCurrentDateProvider *)dateProvider; @property (nonatomic, assign, readonly) SentryScreenFrames *currentFrames; @property (nonatomic, assign, readonly) BOOL isRunning; @@ -34,6 +36,9 @@ NS_ASSUME_NONNULL_BEGIN - (void)start; - (void)stop; +- (CFTimeInterval)getFrameDelay:(uint64_t)startSystemTimestamp + endSystemTimestamp:(uint64_t)endSystemTimestamp; + - (void)addListener:(id)listener; - (void)removeListener:(id)listener; diff --git a/Sources/Sentry/include/SentryTime.h b/Sources/Sentry/include/SentryTime.h index 3985b60d12a..1c07f3fc978 100644 --- a/Sources/Sentry/include/SentryTime.h +++ b/Sources/Sentry/include/SentryTime.h @@ -11,6 +11,8 @@ SENTRY_EXTERN_C_BEGIN */ uint64_t timeIntervalToNanoseconds(double seconds); +double nanosecondsToTimeInterval(uint64_t nanoseconds); + /** * Returns the absolute timestamp, which has no defined reference point or unit * as it is platform dependent. diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index 16bd53155af..ee28fe37089 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -9,15 +9,16 @@ class SentryFramesTrackerTests: XCTestCase { var displayLinkWrapper: TestDisplayLinkWrapper var queue: DispatchQueue + var dateProvider = TestCurrentDateProvider() lazy var hub = TestHub(client: nil, andScope: nil) lazy var tracer = SentryTracer(transactionContext: TransactionContext(name: "test transaction", operation: "test operation"), hub: hub) init() { - displayLinkWrapper = TestDisplayLinkWrapper() + displayLinkWrapper = TestDisplayLinkWrapper(dateProvider: dateProvider) queue = DispatchQueue(label: "SentryFramesTrackerTests", qos: .background, attributes: [.concurrent]) } - lazy var sut: SentryFramesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper) + lazy var sut: SentryFramesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: dateProvider) } private var fixture: Fixture! @@ -76,12 +77,13 @@ class SentryFramesTrackerTests: XCTestCase { func testSlowFrame() throws { let sut = fixture.sut sut.start() - - fixture.displayLinkWrapper.call() - _ = fixture.displayLinkWrapper.fastestSlowFrame() - fixture.displayLinkWrapper.normalFrame() - _ = fixture.displayLinkWrapper.slowestSlowFrame() - + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.fastestSlowFrame() + displayLink.normalFrame() + _ = displayLink.slowestSlowFrame() + try assert(slow: 2, frozen: 0, total: 3) } @@ -121,6 +123,195 @@ class SentryFramesTrackerTests: XCTestCase { try assert(slow: 0, frozen: 0) } + + /** + * The following test validates one slow and one frozen frame in the time interval. The slow frame starts at + * the beginning of the time interval and the frozen frame stops at the end of the time interval. + * + * [nf][- sf - ][nf][ ---- ff ---- ] | nf = normal frame, sf = slow frame, ff = frozen frame + * [--------- time interval -------] + */ + func testFrameDelay_SlowAndFrozenFrameWithinTimeInterval() { + let sut = fixture.sut + sut.start() + + let startDate = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + displayLink.normalFrame() + _ = displayLink.fastestSlowFrame() + displayLink.normalFrame() + _ = displayLink.slowestSlowFrame() + + let endDate = fixture.dateProvider.systemTime() + + let expectedDelay = displayLink.timeEpsilon + displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + + let actualFrameDelay = sut.getFrameDelay(startDate, endSystemTimestamp: endDate) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + + /** + * The following test validates one delayed frame starting before time interval and ending with the time interval. + * + * [---- delayed frame ---- ] + * [- time interval -- ] + */ + func testDelayedFrameStartsBeforeTimeInterval() { + let timeIntervalAfterFrameStart = 0.5 + + // The slow frame threshold is not included because the delayed frame started before the startDate and the rendering on time happened before the startDate. + let expectedDelay = fixture.displayLinkWrapper.frozenFrameThreshold - timeIntervalAfterFrameStart + + testFrameDelay(timeIntervalAfterFrameStart: timeIntervalAfterFrameStart, expectedDelay: expectedDelay) + } + + /** + * The following test validates one delayed frame starting shortly before time interval and ending with the time interval. + * Parts of the expected frame duration overlap with the beginning of the time interval, and are therefore not added to + * the frame delay. + * + * [| e | delayed frame ---- ] e = the expected frame duration + * [---- time interval ---- ] + */ + func testDelayedFrameStartsShortlyBeforeTimeInterval_OnlyDelayedPartAdded() { + let timeIntervalAfterFrameStart = 0.0001 + + // The timeIntervalAfterFrameStart is not subtracted from the delay, because that's when the frame was expected to be rendered on time. + let expectedDelay = fixture.displayLinkWrapper.frozenFrameThreshold - slowFrameThreshold(fixture.displayLinkWrapper.currentFrameRate.rawValue) + + testFrameDelay(timeIntervalAfterFrameStart: timeIntervalAfterFrameStart, expectedDelay: expectedDelay) + } + + /** + * The following test validates one delayed frame starting shortly before time interval and ending after the time interval. + * Parts of the expected frame duration overlap with the beginning of the time interval, and are therefore not added to + * the frame delay. + * + * [| e | delayed frame ------ ] e = the expected frame duration + * [---- time interval ---- ] + */ + func testDelayedFrameStartsAndEndsBeforeTimeInterval_OnlyDelayedPartAdded() { + let displayLink = fixture.displayLinkWrapper + + let timeIntervalAfterFrameStart = 0.1 + let timeIntervalBeforeFrameEnd = 0.01 + + // The slow frame threshold is not included because the startDate is after the frame rendered on time. + let expectedDelay = displayLink.frozenFrameThreshold - timeIntervalAfterFrameStart - timeIntervalBeforeFrameEnd + + testFrameDelay(timeIntervalAfterFrameStart: timeIntervalAfterFrameStart, timeIntervalBeforeFrameEnd: timeIntervalBeforeFrameEnd, expectedDelay: expectedDelay) + } + + /** + * The following test validates two delayed frames. The delay of the first one is fully added to the frame delay. + * No delay of the second frame is added because only the expected frame duration overlaps with the time interval. + * + * [| e | delayed frame ] [| e | delayed frame - ] e = the expected frame duration + * [------ time interval ----- ] + */ + func testOneDelayedFrameStartsShortlyEndsBeforeTimeInterval() { + let sut = fixture.sut + sut.start() + + let startDate = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + displayLink.normalFrame() + _ = displayLink.fastestSlowFrame() + + let timeIntervalBeforeFrameEnd = slowFrameThreshold(displayLink.currentFrameRate.rawValue) - 0.005 + let endDate = fixture.dateProvider.systemTime() - timeIntervalToNanoseconds(timeIntervalBeforeFrameEnd) + + let expectedDelay = displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + + let actualFrameDelay = sut.getFrameDelay(startDate, endSystemTimestamp: endDate) + 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() + + let slowFrameStartDate = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + let endDate = fixture.dateProvider.systemTime() - timeIntervalToNanoseconds(timeIntervalBeforeFrameEnd) + + let startDate = slowFrameStartDate + timeIntervalToNanoseconds(timeIntervalAfterFrameStart) + + let actualFrameDelay = sut.getFrameDelay(startDate, endSystemTimestamp: endDate) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + + func testFrameDelay_WithStartBeforeEnd_Returns0() { + let sut = fixture.sut + sut.start() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + let actualFrameDelay = sut.getFrameDelay(1, endSystemTimestamp: 0) + expect(actualFrameDelay).to(beCloseTo(0.0, within: 0.0001)) + } + + func testFrameDelay_LongestTimeStamp() { + let sut = fixture.sut + sut.start() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + let expectedDelay = displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + + let actualFrameDelay = sut.getFrameDelay(0, endSystemTimestamp: UInt64.max) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + + func testFrameDelay_TimeSpanBiggerThanRecordOfDelayedFrames_Return0() { + let sut = fixture.sut + sut.start() + + let capacity = 1_024 + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + + for _ in 0..<(capacity * 2) { + _ = displayLink.slowestSlowFrame() + } + + // We don't know what the frame delay was as the timespan is bigger + let actualFrameDelay = sut.getFrameDelay(0, endSystemTimestamp: UInt64.max) + expect(actualFrameDelay) == -1.0 + } + + func testFrameDelay_KeepAddingSlowFrames_OnlyTheLast1024SlowFramesAreReturned() { + let sut = fixture.sut + sut.start() + + let capacity = 1_024 + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + + for _ in 0..<(capacity * 2) { + _ = displayLink.slowestSlowFrame() + } + + let expectedDelay = (displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue)) * Double(capacity) + + let actualFrameDelay = sut.getFrameDelay(0, endSystemTimestamp: UInt64.max) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } func testAddListener() { let sut = fixture.sut @@ -167,7 +358,7 @@ class SentryFramesTrackerTests: XCTestCase { func testDealloc_CallsStop() { func sutIsDeallocatedAfterCallingMe() { - _ = SentryFramesTracker(displayLinkWrapper: fixture.displayLinkWrapper) + _ = SentryFramesTracker(displayLinkWrapper: fixture.displayLinkWrapper, dateProvider: fixture.dateProvider) } sutIsDeallocatedAfterCallingMe() From 250f944689057582ea0b87a2350163223c822d90 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Mon, 4 Dec 2023 10:44:15 +0100 Subject: [PATCH 08/33] backup --- Sources/Sentry/SentryFramesTracker.m | 74 ++++++--- Sources/Sentry/SentrySpan.m | 14 +- Sources/Sentry/SentryTracer.m | 16 +- .../SentryFramesTrackerTests.swift | 155 +++++++++++++----- 4 files changed, 187 insertions(+), 72 deletions(-) diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index 9e85f1f05e7..e35ee42c337 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -58,6 +58,7 @@ - (instancetype)initWithStartTimestamp:(uint64_t)startSystemTimestamp @property (nonatomic, strong, readonly) SentryCurrentDateProvider *dateProvider; @property (nonatomic, assign) CFTimeInterval previousFrameTimestamp; @property (nonatomic) uint64_t previousFrameSystemTimestamp; +@property (nonatomic) uint64_t currentFrameRate; @property (nonatomic, strong) NSHashTable> *listeners; # if SENTRY_TARGET_PROFILING_SUPPORTED @property (nonatomic, readwrite) SentryMutableFrameInfoTimeSeries *frozenFrameTimestamps; @@ -95,8 +96,8 @@ - (instancetype)initWithDisplayLinkWrapper:(SentryDisplayLinkWrapper *)displayLi _displayLinkWrapper = displayLinkWrapper; _dateProvider = dateProvider; _listeners = [NSHashTable weakObjectsHashTable]; - _delayedFrames = [[NSMutableArray alloc] initWithCapacity:SentryDelayedFramesCapacity]; - _delayedFrameWriteIndex = 0; + + _currentFrameRate = 60; [self resetFrames]; SENTRY_LOG_DEBUG(@"Initialized frame tracker %@", self); } @@ -120,6 +121,8 @@ - (void)resetFrames # if SENTRY_TARGET_PROFILING_SUPPORTED [self resetProfilingTimestamps]; # endif // SENTRY_TARGET_PROFILING_SUPPORTED + + [self resetDelayedFramesTimeStamps]; } # if SENTRY_TARGET_PROFILING_SUPPORTED @@ -131,6 +134,17 @@ - (void)resetProfilingTimestamps } # endif // SENTRY_TARGET_PROFILING_SUPPORTED +- (void)resetDelayedFramesTimeStamps +{ + _delayedFrames = [[NSMutableArray alloc] initWithCapacity:SentryDelayedFramesCapacity]; + SentryDelayedFrame *initialFrame = + [[SentryDelayedFrame alloc] initWithStartTimestamp:[self.dateProvider systemTime] + expectedDuration:0 + actualDuration:0]; + [_delayedFrames addObject:initialFrame]; + _delayedFrameWriteIndex = 1; +} + - (void)start { if (_isRunning) { @@ -161,11 +175,11 @@ - (void)displayLinkCallback // need to check the frame rate for every callback. // targetTimestamp is only available on iOS 10.0 and tvOS 10.0 and above. We use a fallback of // 60 fps. - uint64_t currentFrameRate = 60; + _currentFrameRate = 60; if (UNLIKELY((self.displayLinkWrapper.targetTimestamp == self.displayLinkWrapper.timestamp))) { - currentFrameRate = 60; + _currentFrameRate = 60; } else { - currentFrameRate = (uint64_t)round( + _currentFrameRate = (uint64_t)round( (1 / (self.displayLinkWrapper.targetTimestamp - self.displayLinkWrapper.timestamp))); } @@ -174,12 +188,12 @@ - (void)displayLinkCallback BOOL hasNoFrameRatesYet = self.frameRateTimestamps.count == 0; uint64_t previousFrameRate = self.frameRateTimestamps.lastObject[@"value"].unsignedLongLongValue; - BOOL frameRateChanged = previousFrameRate != currentFrameRate; + BOOL frameRateChanged = previousFrameRate != _currentFrameRate; BOOL shouldRecordNewFrameRate = hasNoFrameRatesYet || frameRateChanged; if (shouldRecordNewFrameRate) { SENTRY_LOG_DEBUG(@"Recording new frame rate at %llu.", thisFrameSystemTimestamp); [self recordTimestamp:thisFrameSystemTimestamp - value:@(currentFrameRate) + value:@(_currentFrameRate) array:self.frameRateTimestamps]; } } @@ -187,7 +201,7 @@ - (void)displayLinkCallback CFTimeInterval frameDuration = thisFrameTimestamp - self.previousFrameTimestamp; - if (frameDuration > slowFrameThreshold(currentFrameRate) + if (frameDuration > slowFrameThreshold(_currentFrameRate) && frameDuration <= SentryFrozenFrameThreshold) { _slowFrames++; # if SENTRY_TARGET_PROFILING_SUPPORTED @@ -207,9 +221,9 @@ - (void)displayLinkCallback # endif // SENTRY_TARGET_PROFILING_SUPPORTED } - if (frameDuration > slowFrameThreshold(currentFrameRate)) { + if (frameDuration > slowFrameThreshold(_currentFrameRate)) { [self recordDelayedFrame:self.previousFrameSystemTimestamp - expectedDuration:slowFrameThreshold(currentFrameRate) + expectedDuration:slowFrameThreshold(_currentFrameRate) actualDuration:frameDuration]; } @@ -285,12 +299,34 @@ - (void)recordDelayedFrame:(uint64_t)startSystemTimestamp - (CFTimeInterval)getFrameDelay:(uint64_t)startSystemTimestamp endSystemTimestamp:(uint64_t)endSystemTimestamp { - CFTimeInterval delay = 0.0; + CFTimeInterval cantCalculateFrameDelay = -1.0; + + if (_isRunning == NO) { + SENTRY_LOG_DEBUG(@"Not calculating frames delay because frames tracker isn't running."); + return cantCalculateFrameDelay; + } if (startSystemTimestamp >= endSystemTimestamp) { - return delay; + SENTRY_LOG_DEBUG(@"Not calculating frames delay because startSystemTimestamp is before " + @"endSystemTimestamp"); + return cantCalculateFrameDelay; + } + + if (endSystemTimestamp > self.dateProvider.systemTime) { + SENTRY_LOG_DEBUG(@"Not calculating frames delay endSystemTimestamp is in the future."); + return cantCalculateFrameDelay; } + // Check if there is an delayed frame going on but not recorded yet. + CFTimeInterval thisFrameTimestamp = self.displayLinkWrapper.timestamp; + CFTimeInterval frameDuration = thisFrameTimestamp - self.previousFrameTimestamp; + CFTimeInterval ongoingDelayedFrame = 0.0; + if (frameDuration > slowFrameThreshold(_currentFrameRate)) { + ongoingDelayedFrame = frameDuration - slowFrameThreshold(_currentFrameRate); + } + + CFTimeInterval delay = ongoingDelayedFrame; + @synchronized(self.delayedFrames) { // Although we use a ring buffer, and it could take a while until we get to frames within @@ -301,26 +337,15 @@ - (CFTimeInterval)getFrameDelay:(uint64_t)startSystemTimestamp // either because, again, we need to iterate over all elements in the worst case. uint64_t oldestDelayedFrameStartTimestamp = UINT64_MAX; - uint64_t newestDelayedFrameEndTimestamp = 0; for (SentryDelayedFrame *frame in self.delayedFrames) { if (frame.startSystemTimestamp < oldestDelayedFrameStartTimestamp) { oldestDelayedFrameStartTimestamp = frame.startSystemTimestamp; } - - uint64_t frameEndSystemTimeStamp - = frame.startSystemTimestamp + timeIntervalToNanoseconds(frame.actualDuration); - if (frame.startSystemTimestamp < newestDelayedFrameEndTimestamp) { - newestDelayedFrameEndTimestamp = frameEndSystemTimeStamp; - } } if (oldestDelayedFrameStartTimestamp > startSystemTimestamp) { - return -1.0; - } - - if (newestDelayedFrameEndTimestamp < endSystemTimestamp) { - return -1.0; + return cantCalculateFrameDelay; } for (SentryDelayedFrame *frame in self.delayedFrames) { @@ -373,6 +398,7 @@ - (void)stop { _isRunning = NO; [self.displayLinkWrapper invalidate]; + [self resetDelayedFramesTimeStamps]; } - (void)dealloc diff --git a/Sources/Sentry/SentrySpan.m b/Sources/Sentry/SentrySpan.m index 3caa32accaa..17528bcb557 100644 --- a/Sources/Sentry/SentrySpan.m +++ b/Sources/Sentry/SentrySpan.m @@ -40,6 +40,7 @@ @implementation SentrySpan { NSUInteger initSlowFrames; NSUInteger initFrozenFrames; SentryFramesTracker *_framesTracker; + uint64_t startSystemTime; #endif // SENTRY_HAS_UIKIT } @@ -50,6 +51,7 @@ - (instancetype)initWithContext:(SentrySpanContext *)context { if (self = [super init]) { self.startTimestamp = [SentryDependencyContainer.sharedInstance.dateProvider date]; + startSystemTime = SentryDependencyContainer.sharedInstance.dateProvider.systemTime; _data = [[NSMutableDictionary alloc] init]; SentryCrashThread currentThread = sentrycrashthread_self(); @@ -208,6 +210,13 @@ - (void)finishWithStatus:(SentrySpanStatus)status #if SENTRY_HAS_UIKIT if (_framesTracker.isRunning) { + CFTimeInterval framesDelay = [_framesTracker + getFrameDelay: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; @@ -218,8 +227,9 @@ - (void)finishWithStatus:(SentrySpanStatus)status [self setDataValue:@(slowFrames) forKey:@"frames.slow"]; [self setDataValue:@(frozenFrames) forKey:@"frames.frozen"]; - SENTRY_LOG_DEBUG(@"Frames for span \"%@\" Total:%ld Slow:%ld Frozen:%ld", - self.operation, (long)totalFrames, (long)slowFrames, (long)frozenFrames); + SENTRY_LOG_DEBUG(@"Frames for span \"%@\" Total:%ld Slow:%ld Frozen:%ld Delay:%f ms", + self.operation, (long)totalFrames, (long)slowFrames, (long)frozenFrames, + framesDelay * 1000); } } diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 634394b17a3..10eb84b7301 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -751,22 +751,24 @@ - (void)addMeasurements:(SentryTransaction *)transaction NSInteger slowFrames = currentFrames.slow - initSlowFrames; NSInteger frozenFrames = currentFrames.frozen - initFrozenFrames; - CFTimeInterval frameDelay = [framesTracker + CFTimeInterval framesDelay = [framesTracker getFrameDelay:self.startSystemTime endSystemTimestamp:SentryDependencyContainer.sharedInstance.dateProvider.systemTime]; + if (framesDelay >= 0) { + [self setMeasurement:@"frames_delay" + value:@(framesDelay) + unit:SentryMeasurementUnitDuration.second]; + } if (sentryShouldAddSlowFrozenFramesData(totalFrames, slowFrames, frozenFrames)) { [self setMeasurement:@"frames_total" value:@(totalFrames)]; [self setMeasurement:@"frames_slow" value:@(slowFrames)]; [self setMeasurement:@"frames_frozen" value:@(frozenFrames)]; - [self setMeasurement:@"frames_delay" - value:@(frameDelay) - unit:SentryMeasurementUnitDuration.second]; - SENTRY_LOG_DEBUG(@"FrameDelay: Frames for transaction \"%@\" Total:%ld Slow:%ld " - @"Frozen:%ld delay:%f ms", + SENTRY_LOG_DEBUG(@"Frames for transaction \"%@\" Total:%ld Slow:%ld " + @"Frozen:%ld Delay:%f ms", self.operation, (long)totalFrames, (long)slowFrames, (long)frozenFrames, - frameDelay * 1000); + framesDelay * 1000); } } } diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index ee28fe37089..1a4af3f2a6a 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -22,6 +22,8 @@ class SentryFramesTrackerTests: XCTestCase { } private var fixture: Fixture! + + private let frameDelayCapacity = 1_024 override func setUp() { super.setUp() @@ -152,6 +154,33 @@ class SentryFramesTrackerTests: XCTestCase { expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } + /** + * When there is no frame information around yet, because the frame about to be drawn is still delayed, + * the delay should be returned as such. + * + * [nf][ ------- ?? ------ ] | nf = normal frame, ?? = No frame information + * [---- time interval ----] + */ + func testFrameDelay_NoFrameRenderedButShouldHave_DelayReturned() { + let sut = fixture.sut + sut.start() + + let startDate = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + displayLink.normalFrame() + + let delayWithoutFrameRecord = 1.0 + fixture.dateProvider.advance(by: delayWithoutFrameRecord) + let endDate = fixture.dateProvider.systemTime() + + let expectedDelay = delayWithoutFrameRecord - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + + let actualFrameDelay = sut.getFrameDelay(startDate, endSystemTimestamp: endDate) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + /** * The following test validates one delayed frame starting before time interval and ending with the time interval. * @@ -204,6 +233,24 @@ class SentryFramesTrackerTests: XCTestCase { testFrameDelay(timeIntervalAfterFrameStart: timeIntervalAfterFrameStart, timeIntervalBeforeFrameEnd: timeIntervalBeforeFrameEnd, expectedDelay: expectedDelay) } + private func testFrameDelay(timeIntervalAfterFrameStart: TimeInterval = 0.0, timeIntervalBeforeFrameEnd: TimeInterval = 0.0, expectedDelay: TimeInterval) { + let sut = fixture.sut + sut.start() + + let slowFrameStartDate = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + let endDate = fixture.dateProvider.systemTime() - timeIntervalToNanoseconds(timeIntervalBeforeFrameEnd) + + let startDate = slowFrameStartDate + timeIntervalToNanoseconds(timeIntervalAfterFrameStart) + + let actualFrameDelay = sut.getFrameDelay(startDate, endSystemTimestamp: endDate) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + /** * The following test validates two delayed frames. The delay of the first one is fully added to the frame delay. * No delay of the second frame is added because only the expected frame duration overlaps with the time interval. @@ -232,85 +279,103 @@ class SentryFramesTrackerTests: XCTestCase { expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } - private func testFrameDelay(timeIntervalAfterFrameStart: TimeInterval = 0.0, timeIntervalBeforeFrameEnd: TimeInterval = 0.0, expectedDelay: TimeInterval) { + func testFrameDelay_WithStartBeforeEnd_ReturnsMinusOne() { let sut = fixture.sut sut.start() - - let slowFrameStartDate = fixture.dateProvider.systemTime() let displayLink = fixture.displayLinkWrapper displayLink.call() _ = displayLink.slowestSlowFrame() - let endDate = fixture.dateProvider.systemTime() - timeIntervalToNanoseconds(timeIntervalBeforeFrameEnd) - - let startDate = slowFrameStartDate + timeIntervalToNanoseconds(timeIntervalAfterFrameStart) - - let actualFrameDelay = sut.getFrameDelay(startDate, endSystemTimestamp: endDate) - expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + let actualFrameDelay = sut.getFrameDelay(1, endSystemTimestamp: 0) + expect(actualFrameDelay) == -1.0 } - func testFrameDelay_WithStartBeforeEnd_Returns0() { + func testFrameDelay_LongestTimeStamp_ReturnsMinusOne() { let sut = fixture.sut sut.start() let displayLink = fixture.displayLinkWrapper displayLink.call() _ = displayLink.slowestSlowFrame() - - let actualFrameDelay = sut.getFrameDelay(1, endSystemTimestamp: 0) - expect(actualFrameDelay).to(beCloseTo(0.0, within: 0.0001)) + + let actualFrameDelay = sut.getFrameDelay(0, endSystemTimestamp: UInt64.max) + expect(actualFrameDelay) == -1.0 } - func testFrameDelay_LongestTimeStamp() { + func testFrameDelay_KeepAddingSlowFrames_OnlyTheCapacityFramesReturned() { + let displayLink = fixture.displayLinkWrapper let sut = fixture.sut sut.start() - let displayLink = fixture.displayLinkWrapper - displayLink.call() - _ = displayLink.slowestSlowFrame() + let startSystemTimeStamp = givenDelayedFramesCapacityFull() - let expectedDelay = displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + let endDate = fixture.dateProvider.systemTime() + + let expectedDelay = (displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue)) * Double(frameDelayCapacity) - let actualFrameDelay = sut.getFrameDelay(0, endSystemTimestamp: UInt64.max) + let actualFrameDelay = sut.getFrameDelay(startSystemTimeStamp, endSystemTimestamp: endDate) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } - func testFrameDelay_TimeSpanBiggerThanRecordOfDelayedFrames_Return0() { + func testFrameDelay_CapacityFull_FrameInformationMissing_DelayReturned() { let sut = fixture.sut + let displayLink = fixture.displayLinkWrapper sut.start() - let capacity = 1_024 + let startSystemTimeStamp = givenDelayedFramesCapacityFull() - let displayLink = fixture.displayLinkWrapper - displayLink.call() + let delayWithoutFrameRecord = 2.0 + fixture.dateProvider.advance(by: delayWithoutFrameRecord) + let endDate = fixture.dateProvider.systemTime() - for _ in 0..<(capacity * 2) { - _ = displayLink.slowestSlowFrame() - } + let delayNotRecorded = delayWithoutFrameRecord - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + + let expectedDelay = (displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue)) * Double(frameDelayCapacity) + delayNotRecorded - // We don't know what the frame delay was as the timespan is bigger - let actualFrameDelay = sut.getFrameDelay(0, endSystemTimestamp: UInt64.max) + let actualFrameDelay = sut.getFrameDelay(startSystemTimeStamp, endSystemTimestamp: endDate) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + + func testFrameDelay_CapacityFull_StartTimeTooEarly_ReturnsMinusOne() { + let sut = fixture.sut + sut.start() + + let startSystemTimeStamp = givenDelayedFramesCapacityFull() + + let endDate = fixture.dateProvider.systemTime() + + let actualFrameDelay = sut.getFrameDelay(startSystemTimeStamp - 1, endSystemTimestamp: endDate) + expect(actualFrameDelay).to(beCloseTo(-1, within: 0.0001), description: "startSystemTimeStamp starts one nanosecond before the oldest slow frame. Therefore the frame delay can't be calculated and should me 0.") + } + + func testFrameDelay_FramesTrackerNotRunning_ReturnsMinusOne() { + let sut = fixture.sut + sut.start() + + let startSystemTimeStamp = givenDelayedFramesCapacityFull() + + sut.stop() + + let endDate = fixture.dateProvider.systemTime() + + let actualFrameDelay = sut.getFrameDelay(startSystemTimeStamp, endSystemTimestamp: endDate) expect(actualFrameDelay) == -1.0 } - func testFrameDelay_KeepAddingSlowFrames_OnlyTheLast1024SlowFramesAreReturned() { + func testFrameDelay_RestartTracker_ReturnsMinusOne() { let sut = fixture.sut sut.start() - let capacity = 1_024 + let startSystemTimeStamp = givenDelayedFramesCapacityFull() - let displayLink = fixture.displayLinkWrapper - displayLink.call() + sut.stop() + sut.start() - for _ in 0..<(capacity * 2) { - _ = displayLink.slowestSlowFrame() - } + let endDate = fixture.dateProvider.systemTime() - let expectedDelay = (displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue)) * Double(capacity) - - let actualFrameDelay = sut.getFrameDelay(0, endSystemTimestamp: UInt64.max) - expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + let actualFrameDelay = sut.getFrameDelay(startSystemTimeStamp, endSystemTimestamp: endDate) + expect(actualFrameDelay) == -1.0 } func testAddListener() { @@ -364,6 +429,18 @@ class SentryFramesTrackerTests: XCTestCase { XCTAssertEqual(1, fixture.displayLinkWrapper.invalidateInvocations.count) } + + private func givenDelayedFramesCapacityFull() -> UInt64 { + let displayLink = fixture.displayLinkWrapper + displayLink.call() + + for _ in 0..<(frameDelayCapacity + 1) { + _ = displayLink.slowestSlowFrame() + } + + // Where the second frame starts + return timeIntervalToNanoseconds(displayLink.frozenFrameThreshold) + } } private class FrameTrackerListener: NSObject, SentryFramesTrackerListener { From 7f83a8e451638503db2a54637b7360179bff2ecc Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Mon, 4 Dec 2023 10:55:02 +0100 Subject: [PATCH 09/33] async test --- .../SentryFramesTrackerTests.swift | 81 ++++++++++++------- 1 file changed, 54 insertions(+), 27 deletions(-) diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index 1a4af3f2a6a..b5597082c9b 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -137,7 +137,7 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let startDate = fixture.dateProvider.systemTime() + let startSystemTime = fixture.dateProvider.systemTime() let displayLink = fixture.displayLinkWrapper displayLink.call() @@ -146,11 +146,11 @@ class SentryFramesTrackerTests: XCTestCase { displayLink.normalFrame() _ = displayLink.slowestSlowFrame() - let endDate = fixture.dateProvider.systemTime() + let endSystemTime = fixture.dateProvider.systemTime() let expectedDelay = displayLink.timeEpsilon + displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue) - let actualFrameDelay = sut.getFrameDelay(startDate, endSystemTimestamp: endDate) + let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } @@ -165,7 +165,7 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let startDate = fixture.dateProvider.systemTime() + let startSystemTime = fixture.dateProvider.systemTime() let displayLink = fixture.displayLinkWrapper displayLink.call() @@ -173,11 +173,11 @@ class SentryFramesTrackerTests: XCTestCase { let delayWithoutFrameRecord = 1.0 fixture.dateProvider.advance(by: delayWithoutFrameRecord) - let endDate = fixture.dateProvider.systemTime() + let endSystemTime = fixture.dateProvider.systemTime() let expectedDelay = delayWithoutFrameRecord - slowFrameThreshold(displayLink.currentFrameRate.rawValue) - let actualFrameDelay = sut.getFrameDelay(startDate, endSystemTimestamp: endDate) + let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } @@ -237,17 +237,17 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let slowFrameStartDate = fixture.dateProvider.systemTime() + let slowFrameStartSystemTime = fixture.dateProvider.systemTime() let displayLink = fixture.displayLinkWrapper displayLink.call() _ = displayLink.slowestSlowFrame() - let endDate = fixture.dateProvider.systemTime() - timeIntervalToNanoseconds(timeIntervalBeforeFrameEnd) + let endSystemTime = fixture.dateProvider.systemTime() - timeIntervalToNanoseconds(timeIntervalBeforeFrameEnd) - let startDate = slowFrameStartDate + timeIntervalToNanoseconds(timeIntervalAfterFrameStart) + let startSystemTime = slowFrameStartSystemTime + timeIntervalToNanoseconds(timeIntervalAfterFrameStart) - let actualFrameDelay = sut.getFrameDelay(startDate, endSystemTimestamp: endDate) + let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } @@ -262,7 +262,7 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let startDate = fixture.dateProvider.systemTime() + let startSystemTime = fixture.dateProvider.systemTime() let displayLink = fixture.displayLinkWrapper displayLink.call() @@ -271,11 +271,11 @@ class SentryFramesTrackerTests: XCTestCase { _ = displayLink.fastestSlowFrame() let timeIntervalBeforeFrameEnd = slowFrameThreshold(displayLink.currentFrameRate.rawValue) - 0.005 - let endDate = fixture.dateProvider.systemTime() - timeIntervalToNanoseconds(timeIntervalBeforeFrameEnd) + let endSystemTime = fixture.dateProvider.systemTime() - timeIntervalToNanoseconds(timeIntervalBeforeFrameEnd) let expectedDelay = displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue) - let actualFrameDelay = sut.getFrameDelay(startDate, endSystemTimestamp: endDate) + let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } @@ -308,13 +308,13 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let startSystemTimeStamp = givenDelayedFramesCapacityFull() + let startSystemTime = givenDelayedFramesCapacityFull() - let endDate = fixture.dateProvider.systemTime() + let endSystemTime = fixture.dateProvider.systemTime() let expectedDelay = (displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue)) * Double(frameDelayCapacity) - let actualFrameDelay = sut.getFrameDelay(startSystemTimeStamp, endSystemTimestamp: endDate) + let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } @@ -323,17 +323,17 @@ class SentryFramesTrackerTests: XCTestCase { let displayLink = fixture.displayLinkWrapper sut.start() - let startSystemTimeStamp = givenDelayedFramesCapacityFull() + let startSystemTime = givenDelayedFramesCapacityFull() let delayWithoutFrameRecord = 2.0 fixture.dateProvider.advance(by: delayWithoutFrameRecord) - let endDate = fixture.dateProvider.systemTime() + let endSystemTime = fixture.dateProvider.systemTime() let delayNotRecorded = delayWithoutFrameRecord - slowFrameThreshold(displayLink.currentFrameRate.rawValue) let expectedDelay = (displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue)) * Double(frameDelayCapacity) + delayNotRecorded - let actualFrameDelay = sut.getFrameDelay(startSystemTimeStamp, endSystemTimestamp: endDate) + let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } @@ -341,11 +341,11 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let startSystemTimeStamp = givenDelayedFramesCapacityFull() + let startSystemTime = givenDelayedFramesCapacityFull() - let endDate = fixture.dateProvider.systemTime() + let endSystemTime = fixture.dateProvider.systemTime() - let actualFrameDelay = sut.getFrameDelay(startSystemTimeStamp - 1, endSystemTimestamp: endDate) + let actualFrameDelay = sut.getFrameDelay(startSystemTime - 1, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(-1, within: 0.0001), description: "startSystemTimeStamp starts one nanosecond before the oldest slow frame. Therefore the frame delay can't be calculated and should me 0.") } @@ -353,13 +353,13 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let startSystemTimeStamp = givenDelayedFramesCapacityFull() + let startSystemTime = givenDelayedFramesCapacityFull() sut.stop() - let endDate = fixture.dateProvider.systemTime() + let endSystemTime = fixture.dateProvider.systemTime() - let actualFrameDelay = sut.getFrameDelay(startSystemTimeStamp, endSystemTimestamp: endDate) + let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay) == -1.0 } @@ -372,11 +372,38 @@ class SentryFramesTrackerTests: XCTestCase { sut.stop() sut.start() - let endDate = fixture.dateProvider.systemTime() + let endSystemTime = fixture.dateProvider.systemTime() - let actualFrameDelay = sut.getFrameDelay(startSystemTimeStamp, endSystemTimestamp: endDate) + let actualFrameDelay = sut.getFrameDelay(startSystemTimeStamp, endSystemTimestamp: endSystemTime) expect(actualFrameDelay) == -1.0 } + + func testFrameDelay_GetInfoFromBackgroundThreadWhileAdding() { + let sut = fixture.sut + sut.start() + + let startSystemTimeStamp = givenDelayedFramesCapacityFull() + let endSystemTime = fixture.dateProvider.systemTime() + + let loopSize = 1_000 + let expectation = expectation(description: "Get Frames Delays") + expectation.expectedFulfillmentCount = loopSize + + for _ in 0..= -1 + + expectation.fulfill() + } + } + + _ = givenDelayedFramesCapacityFull() + + wait(for: [expectation], timeout: 3.0) + } func testAddListener() { let sut = fixture.sut From 65b98c891a2033e6efcf52a895f8d7e377bb2843 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Mon, 4 Dec 2023 11:08:27 +0100 Subject: [PATCH 10/33] SentryDelayedFrame to extra class --- Sentry.xcodeproj/project.pbxproj | 8 ++++++ Sources/Sentry/SentryDelayedFrame.m | 25 +++++++++++++++++ Sources/Sentry/SentryFramesTracker.m | 30 +-------------------- Sources/Sentry/include/SentryDelayedFrame.h | 22 +++++++++++++++ 4 files changed, 56 insertions(+), 29 deletions(-) create mode 100644 Sources/Sentry/SentryDelayedFrame.m create mode 100644 Sources/Sentry/include/SentryDelayedFrame.h diff --git a/Sentry.xcodeproj/project.pbxproj b/Sentry.xcodeproj/project.pbxproj index bf9a78c66a1..a7fab6e3656 100644 --- a/Sentry.xcodeproj/project.pbxproj +++ b/Sentry.xcodeproj/project.pbxproj @@ -81,6 +81,8 @@ 622C08DB29E554B9002571D4 /* SentrySpanContext+Private.h in Headers */ = {isa = PBXBuildFile; fileRef = 622C08D929E554B9002571D4 /* SentrySpanContext+Private.h */; }; 623C45B02A651D8200D9E88B /* SentryCoreDataTracker+Test.m in Sources */ = {isa = PBXBuildFile; fileRef = 623C45AF2A651D8200D9E88B /* SentryCoreDataTracker+Test.m */; }; 627E7589299F6FE40085504D /* SentryInternalDefines.h in Headers */ = {isa = PBXBuildFile; fileRef = 627E7588299F6FE40085504D /* SentryInternalDefines.h */; }; + 62862B1C2B1DDBC8009B16E3 /* SentryDelayedFrame.h in Headers */ = {isa = PBXBuildFile; fileRef = 62862B1B2B1DDBC8009B16E3 /* SentryDelayedFrame.h */; }; + 62862B1E2B1DDC35009B16E3 /* SentryDelayedFrame.m in Sources */ = {isa = PBXBuildFile; fileRef = 62862B1D2B1DDC35009B16E3 /* SentryDelayedFrame.m */; }; 62885DA729E946B100554F38 /* TestConncurrentModifications.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62885DA629E946B100554F38 /* TestConncurrentModifications.swift */; }; 62950F1029E7FE0100A42624 /* SentryTransactionContextTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62950F0F29E7FE0100A42624 /* SentryTransactionContextTests.swift */; }; 629690532AD3E060000185FA /* SentryReachabilitySwiftTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 629690522AD3E060000185FA /* SentryReachabilitySwiftTests.swift */; }; @@ -969,6 +971,8 @@ 623C45AE2A651C4500D9E88B /* SentryCoreDataTracker+Test.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = "SentryCoreDataTracker+Test.h"; sourceTree = ""; }; 623C45AF2A651D8200D9E88B /* SentryCoreDataTracker+Test.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = "SentryCoreDataTracker+Test.m"; sourceTree = ""; }; 627E7588299F6FE40085504D /* SentryInternalDefines.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryInternalDefines.h; path = include/SentryInternalDefines.h; sourceTree = ""; }; + 62862B1B2B1DDBC8009B16E3 /* SentryDelayedFrame.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryDelayedFrame.h; path = include/SentryDelayedFrame.h; sourceTree = ""; }; + 62862B1D2B1DDC35009B16E3 /* SentryDelayedFrame.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryDelayedFrame.m; sourceTree = ""; }; 62885DA629E946B100554F38 /* TestConncurrentModifications.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = TestConncurrentModifications.swift; sourceTree = ""; }; 62950F0F29E7FE0100A42624 /* SentryTransactionContextTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryTransactionContextTests.swift; sourceTree = ""; }; 629690522AD3E060000185FA /* SentryReachabilitySwiftTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryReachabilitySwiftTests.swift; sourceTree = ""; }; @@ -2902,6 +2906,8 @@ 7B6C5EDD264E8DF00010D138 /* SentryFramesTracker.m */, 7B7A599426B692540060A676 /* SentryScreenFrames.h */, 7B7A599626B692F00060A676 /* SentryScreenFrames.m */, + 62862B1B2B1DDBC8009B16E3 /* SentryDelayedFrame.h */, + 62862B1D2B1DDC35009B16E3 /* SentryDelayedFrame.m */, ); name = FramesTracking; sourceTree = ""; @@ -3523,6 +3529,7 @@ 63B818F91EC34639002FDF4C /* SentryDebugMeta.h in Headers */, 6360850D1ED2AFE100E8599E /* SentryBreadcrumb.h in Headers */, 7BAF3DD92440AEC8008A5414 /* SentryRequestManager.h in Headers */, + 62862B1C2B1DDBC8009B16E3 /* SentryDelayedFrame.h in Headers */, 627E7589299F6FE40085504D /* SentryInternalDefines.h in Headers */, 7BE3C77B2446111500A38442 /* SentryRateLimitParser.h in Headers */, 84A888FD28D9B11700C51DFD /* SentryProfiler+Private.h in Headers */, @@ -4047,6 +4054,7 @@ 63FE712920DA4C1000CDBAE8 /* SentryCrashCPU_arm.c in Sources */, 03F84D3427DD4191008FE43F /* SentryThreadMetadataCache.cpp in Sources */, 7B88F30024BC5A7D00ADF90A /* SentrySdkInfo.m in Sources */, + 62862B1E2B1DDC35009B16E3 /* SentryDelayedFrame.m in Sources */, 84AC61D729F75A98009EEF61 /* SentryDispatchFactory.m in Sources */, 15360CD62432832400112302 /* SentryAutoSessionTrackingIntegration.m in Sources */, 7B63459F280EBA7200CFA05A /* SentryUIEventTracker.m in Sources */, diff --git a/Sources/Sentry/SentryDelayedFrame.m b/Sources/Sentry/SentryDelayedFrame.m new file mode 100644 index 00000000000..9d0290c7319 --- /dev/null +++ b/Sources/Sentry/SentryDelayedFrame.m @@ -0,0 +1,25 @@ +#import "SentryDelayedFrame.h" + +#if SENTRY_HAS_UIKIT + +NS_ASSUME_NONNULL_BEGIN + +@implementation SentryDelayedFrame + +- (instancetype)initWithStartTimestamp:(uint64_t)startSystemTimestamp + expectedDuration:(CFTimeInterval)expectedDuration + actualDuration:(CFTimeInterval)actualDuration +{ + if (self = [super init]) { + _startSystemTimestamp = startSystemTimestamp; + _expectedDuration = expectedDuration; + _actualDuration = actualDuration; + } + return self; +} + +@end + +NS_ASSUME_NONNULL_END + +#endif // SENTRY_HAS_UIKIT diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index e35ee42c337..bf0882eaced 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -4,6 +4,7 @@ # import "SentryCompiler.h" # import "SentryCurrentDateProvider.h" +# import "SentryDelayedFrame.h" # import "SentryDisplayLinkWrapper.h" # import "SentryLog.h" # import "SentryProfiler.h" @@ -22,35 +23,6 @@ static CFTimeInterval const SentryPreviousFrameInitialValue = -1; static NSInteger const SentryDelayedFramesCapacity = 1024; -@interface SentryDelayedFrame : NSObject -SENTRY_NO_INIT - -- (instancetype)initWithStartTimestamp:(uint64_t)startSystemTimestamp - expectedDuration:(CFTimeInterval)expectedDuration - actualDuration:(CFTimeInterval)actualDuration; - -@property (nonatomic, readonly) uint64_t startSystemTimestamp; -@property (nonatomic, readonly) CFTimeInterval expectedDuration; -@property (nonatomic, readonly) CFTimeInterval actualDuration; - -@end - -@implementation SentryDelayedFrame - -- (instancetype)initWithStartTimestamp:(uint64_t)startSystemTimestamp - expectedDuration:(CFTimeInterval)expectedDuration - actualDuration:(CFTimeInterval)actualDuration -{ - if (self = [super init]) { - _startSystemTimestamp = startSystemTimestamp; - _expectedDuration = expectedDuration; - _actualDuration = actualDuration; - } - return self; -} - -@end - @interface SentryFramesTracker () diff --git a/Sources/Sentry/include/SentryDelayedFrame.h b/Sources/Sentry/include/SentryDelayedFrame.h new file mode 100644 index 00000000000..9fe97fc067f --- /dev/null +++ b/Sources/Sentry/include/SentryDelayedFrame.h @@ -0,0 +1,22 @@ +#import "SentryDefines.h" + +#if SENTRY_HAS_UIKIT + +NS_ASSUME_NONNULL_BEGIN + +@interface SentryDelayedFrame : NSObject +SENTRY_NO_INIT + +- (instancetype)initWithStartTimestamp:(uint64_t)startSystemTimestamp + expectedDuration:(CFTimeInterval)expectedDuration + actualDuration:(CFTimeInterval)actualDuration; + +@property (nonatomic, readonly) uint64_t startSystemTimestamp; +@property (nonatomic, readonly) CFTimeInterval expectedDuration; +@property (nonatomic, readonly) CFTimeInterval actualDuration; + +@end + +NS_ASSUME_NONNULL_END + +#endif // SENTRY_HAS_UIKIT From 62707bef4fbfd4f4d88f39544a452d21b98c91f8 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Mon, 4 Dec 2023 11:57:45 +0100 Subject: [PATCH 11/33] ring buffer explanation --- Sources/Sentry/SentryFramesTracker.m | 26 ++++++++++++++++--- .../SentryFramesTrackerTests.swift | 2 +- 2 files changed, 23 insertions(+), 5 deletions(-) diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index bf0882eaced..0adb2e61a1c 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -21,7 +21,28 @@ static CFTimeInterval const SentryFrozenFrameThreshold = 0.7; static CFTimeInterval const SentryPreviousFrameInitialValue = -1; -static NSInteger const SentryDelayedFramesCapacity = 1024; + +/** + * We chose a ring buffer to keep a record of delayed frames because we don't want to do bookkeeping + * of running transactions and spans to know when we can remove delayed frames data, considering + * single-span ingestion on the horizon. + * + * The deadline for auto-generated transactions is 30 seconds (SENTRY_AUTO_TRANSACTION_DEADLINE), + * and the max duration is 500 seconds (SENTRY_AUTO_TRANSACTION_MAX_DURATION). Continuous delayed + * frames slightly over the threshold are unlikely. Instead, we expect longer delays. To guarantee + * reporting correct values for all possible scenarios, we would need to choose a ring buffer size + * of 500 * 118 = 59.000. The SentryDelayedFrame has three properties, with each allocating 8 bytes. + * The overhead of an NSObject is considered to be an extra 8 bytes on 64-bit architecture. So, + * allocating one SentryDelayedFrame should be 32 bytes. With a ring buffer size of 59.000, we would + * allocate 59.000 * 32 ≈ 1,8 MiB, which is too much memory for this feature. Instead, we have to + * use a smaller size. + * + * Let's assume a frame rate of 120 fps, 5% of frame being delayed for roughly 10 ms, which means we + * roughly have to record 6 delayed frames per second. This would mean we need a buffer size of 6 * + * 500 (SENTRY_AUTO_TRANSACTION_DEADLINE) = 3.000. Transactions being that long are unlikely, so + * let's go with 2048 elements, allocating 2048 * 32 bytes = 64 KiB. + */ +static NSInteger const SentryDelayedFramesCapacity = 2048; @interface SentryFramesTracker () @@ -38,9 +59,6 @@ @property (nonatomic, readwrite) SentryMutableFrameInfoTimeSeries *frameRateTimestamps; # endif // SENTRY_TARGET_PROFILING_SUPPORTED -/** - * The delayed frames are stored as a ring buffer to minimize memory footprint. - */ @property (nonatomic, strong) NSMutableArray *delayedFrames; @property (nonatomic) uint8_t delayedFrameWriteIndex; diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index b5597082c9b..e9015776b73 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -23,7 +23,7 @@ class SentryFramesTrackerTests: XCTestCase { private var fixture: Fixture! - private let frameDelayCapacity = 1_024 + private let frameDelayCapacity = 2_048 override func setUp() { super.setUp() From 68e368361d75a82c4359f14d512c490b4303b4bd Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Mon, 4 Dec 2023 13:34:10 +0100 Subject: [PATCH 12/33] backup for removing ring buffer --- Sources/Sentry/SentryFramesTracker.m | 60 ++++++++++--------- Sources/Sentry/SentryTracer.m | 1 - Sources/Sentry/include/SentryTracer.h | 2 + .../SentryFramesTrackerTests.swift | 35 +++++------ 4 files changed, 51 insertions(+), 47 deletions(-) diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index 0adb2e61a1c..568106f2a4b 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -22,28 +22,6 @@ static CFTimeInterval const SentryFrozenFrameThreshold = 0.7; static CFTimeInterval const SentryPreviousFrameInitialValue = -1; -/** - * We chose a ring buffer to keep a record of delayed frames because we don't want to do bookkeeping - * of running transactions and spans to know when we can remove delayed frames data, considering - * single-span ingestion on the horizon. - * - * The deadline for auto-generated transactions is 30 seconds (SENTRY_AUTO_TRANSACTION_DEADLINE), - * and the max duration is 500 seconds (SENTRY_AUTO_TRANSACTION_MAX_DURATION). Continuous delayed - * frames slightly over the threshold are unlikely. Instead, we expect longer delays. To guarantee - * reporting correct values for all possible scenarios, we would need to choose a ring buffer size - * of 500 * 118 = 59.000. The SentryDelayedFrame has three properties, with each allocating 8 bytes. - * The overhead of an NSObject is considered to be an extra 8 bytes on 64-bit architecture. So, - * allocating one SentryDelayedFrame should be 32 bytes. With a ring buffer size of 59.000, we would - * allocate 59.000 * 32 ≈ 1,8 MiB, which is too much memory for this feature. Instead, we have to - * use a smaller size. - * - * Let's assume a frame rate of 120 fps, 5% of frame being delayed for roughly 10 ms, which means we - * roughly have to record 6 delayed frames per second. This would mean we need a buffer size of 6 * - * 500 (SENTRY_AUTO_TRANSACTION_DEADLINE) = 3.000. Transactions being that long are unlikely, so - * let's go with 2048 elements, allocating 2048 * 32 bytes = 64 KiB. - */ -static NSInteger const SentryDelayedFramesCapacity = 2048; - @interface SentryFramesTracker () @@ -126,7 +104,7 @@ - (void)resetProfilingTimestamps - (void)resetDelayedFramesTimeStamps { - _delayedFrames = [[NSMutableArray alloc] initWithCapacity:SentryDelayedFramesCapacity]; + _delayedFrames = [NSMutableArray array]; SentryDelayedFrame *initialFrame = [[SentryDelayedFrame alloc] initWithStartTimestamp:[self.dateProvider systemTime] expectedDuration:0 @@ -269,21 +247,45 @@ - (void)recordDelayedFrame:(uint64_t)startSystemTimestamp actualDuration:(CFTimeInterval)actualDuration { @synchronized(self.delayedFrames) { + [self removeOldDelayedFrames]; + SENTRY_LOG_DEBUG(@"FrameDelay: Record expected:%f ms actual %f ms", expectedDuration * 1000, actualDuration * 1000); SentryDelayedFrame *delayedFrame = [[SentryDelayedFrame alloc] initWithStartTimestamp:startSystemTimestamp expectedDuration:expectedDuration actualDuration:actualDuration]; - if (self.delayedFrames.count < SentryDelayedFramesCapacity) { - [self.delayedFrames addObject:delayedFrame]; + [self.delayedFrames addObject:delayedFrame]; + } +} + +/** + * Removes delayed frame that are older than current time minus + * SENTRY_AUTO_TRANSACTION_MAX_DURATION. + * @note Make sure to call this in a @synchronized block. + */ +- (void)removeOldDelayedFrames +{ + u_int64_t transactionMaxDurationNS + = timeIntervalToNanoseconds(SENTRY_AUTO_TRANSACTION_MAX_DURATION); + + uint64_t removeFramesBeforeSystemTimeStamp + = _dateProvider.systemTime - transactionMaxDurationNS; + if (_dateProvider.systemTime < transactionMaxDurationNS) { + removeFramesBeforeSystemTimeStamp = 0; + } + + NSInteger i = 0; + for (SentryDelayedFrame *frame in self.delayedFrames) { + uint64_t frameEndSystemTimeStamp + = frame.startSystemTimestamp + timeIntervalToNanoseconds(frame.actualDuration); + if (frameEndSystemTimeStamp < removeFramesBeforeSystemTimeStamp) { + i++; } else { - self.delayedFrames[self.delayedFrameWriteIndex] = delayedFrame; + break; } - - self.delayedFrameWriteIndex - = (self.delayedFrameWriteIndex + 1) % SentryDelayedFramesCapacity; } + [self.delayedFrames removeObjectsInRange:NSMakeRange(0, i)]; } - (CFTimeInterval)getFrameDelay:(uint64_t)startSystemTimestamp diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 10eb84b7301..5fb98d38c3b 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -56,7 +56,6 @@ static const NSTimeInterval SENTRY_APP_START_MEASUREMENT_DIFFERENCE = 5.0; #endif // SENTRY_HAS_UIKIT -static const NSTimeInterval SENTRY_AUTO_TRANSACTION_MAX_DURATION = 500.0; static const NSTimeInterval SENTRY_AUTO_TRANSACTION_DEADLINE = 30.0; @interface diff --git a/Sources/Sentry/include/SentryTracer.h b/Sources/Sentry/include/SentryTracer.h index 8dcc38bd4ee..4eb4aeb82bb 100644 --- a/Sources/Sentry/include/SentryTracer.h +++ b/Sources/Sentry/include/SentryTracer.h @@ -11,6 +11,8 @@ NS_ASSUME_NONNULL_BEGIN static NSTimeInterval const SentryTracerDefaultTimeout = 3.0; +static const NSTimeInterval SENTRY_AUTO_TRANSACTION_MAX_DURATION = 500.0; + @protocol SentryTracerDelegate /** diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index e9015776b73..1617f4b2ede 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -22,8 +22,6 @@ class SentryFramesTrackerTests: XCTestCase { } private var fixture: Fixture! - - private let frameDelayCapacity = 2_048 override func setUp() { super.setUp() @@ -308,40 +306,42 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let startSystemTime = givenDelayedFramesCapacityFull() + let startSystemTime = givenMoreDelayedFramesThanTransactionMaxDuration() let endSystemTime = fixture.dateProvider.systemTime() - let expectedDelay = (displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue)) * Double(frameDelayCapacity) + let expectedDelay = (displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue)) let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } - func testFrameDelay_CapacityFull_FrameInformationMissing_DelayReturned() { + func testFrameDelay_MoreThanTransactionMaxDuration_FrameInformationMissing_DelayReturned() { let sut = fixture.sut let displayLink = fixture.displayLinkWrapper sut.start() - let startSystemTime = givenDelayedFramesCapacityFull() + let startSystemTime = givenMoreDelayedFramesThanTransactionMaxDuration() let delayWithoutFrameRecord = 2.0 fixture.dateProvider.advance(by: delayWithoutFrameRecord) let endSystemTime = fixture.dateProvider.systemTime() - let delayNotRecorded = delayWithoutFrameRecord - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + let slowFrames = sut.currentFrames.slow + let slowestSlowFrameDelay = (displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue)) - let expectedDelay = (displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue)) * Double(frameDelayCapacity) + delayNotRecorded + let delayNotRecorded = delayWithoutFrameRecord - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + let expectedDelay = slowestSlowFrameDelay * Double(slowFrames) + delayNotRecorded let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } - func testFrameDelay_CapacityFull_StartTimeTooEarly_ReturnsMinusOne() { + func testFrameDelay_MoreThanTransactionMaxDuration_StartTimeTooEarly_ReturnsMinusOne() { let sut = fixture.sut sut.start() - let startSystemTime = givenDelayedFramesCapacityFull() + let startSystemTime = givenMoreDelayedFramesThanTransactionMaxDuration() let endSystemTime = fixture.dateProvider.systemTime() @@ -353,7 +353,7 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let startSystemTime = givenDelayedFramesCapacityFull() + let startSystemTime = givenMoreDelayedFramesThanTransactionMaxDuration() sut.stop() @@ -367,7 +367,7 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let startSystemTimeStamp = givenDelayedFramesCapacityFull() + let startSystemTimeStamp = givenMoreDelayedFramesThanTransactionMaxDuration() sut.stop() sut.start() @@ -382,7 +382,7 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let startSystemTimeStamp = givenDelayedFramesCapacityFull() + let startSystemTimeStamp = givenMoreDelayedFramesThanTransactionMaxDuration() let endSystemTime = fixture.dateProvider.systemTime() let loopSize = 1_000 @@ -400,7 +400,7 @@ class SentryFramesTrackerTests: XCTestCase { } } - _ = givenDelayedFramesCapacityFull() + _ = givenMoreDelayedFramesThanTransactionMaxDuration() wait(for: [expectation], timeout: 3.0) } @@ -448,7 +448,6 @@ class SentryFramesTrackerTests: XCTestCase { } func testDealloc_CallsStop() { - func sutIsDeallocatedAfterCallingMe() { _ = SentryFramesTracker(displayLinkWrapper: fixture.displayLinkWrapper, dateProvider: fixture.dateProvider) } @@ -457,11 +456,13 @@ class SentryFramesTrackerTests: XCTestCase { XCTAssertEqual(1, fixture.displayLinkWrapper.invalidateInvocations.count) } - private func givenDelayedFramesCapacityFull() -> UInt64 { + private func givenMoreDelayedFramesThanTransactionMaxDuration() -> UInt64 { let displayLink = fixture.displayLinkWrapper displayLink.call() - for _ in 0..<(frameDelayCapacity + 1) { + let transactionMaxDurationNS = timeIntervalToNanoseconds(SENTRY_AUTO_TRANSACTION_MAX_DURATION) + + while transactionMaxDurationNS >= fixture.dateProvider.systemTime() { _ = displayLink.slowestSlowFrame() } From 9d33c24c331886d7c2b204ced3aa4dee531dee4b Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 5 Dec 2023 11:00:08 +0100 Subject: [PATCH 13/33] clean up --- SentryTestUtils/TestDisplayLinkWrapper.swift | 18 ++-- Sources/Sentry/SentryDependencyContainer.m | 4 +- Sources/Sentry/SentryFramesTracker.m | 101 +++++++++--------- Sources/Sentry/include/SentryFramesTracker.h | 3 +- .../SentryFramesTrackerTests.swift | 68 ++++++------ 5 files changed, 108 insertions(+), 86 deletions(-) diff --git a/SentryTestUtils/TestDisplayLinkWrapper.swift b/SentryTestUtils/TestDisplayLinkWrapper.swift index 687c8bbb421..bb74228c005 100644 --- a/SentryTestUtils/TestDisplayLinkWrapper.swift +++ b/SentryTestUtils/TestDisplayLinkWrapper.swift @@ -21,13 +21,20 @@ public class TestDisplayLinkWrapper: SentryDisplayLinkWrapper { public var target: AnyObject! public var selector: Selector! public var currentFrameRate: FrameRate = .low - public let frozenFrameThreshold = 0.7 + let frozenFrameThreshold = 0.7 + public let slowestSlowFrameDuration: Double + public let fastestFrozenFrameDuration: Double + public var dateProvider: TestCurrentDateProvider /// The smallest magnitude of time that is significant to how frames are classified as normal/slow/frozen. public let timeEpsilon = 0.001 public init(dateProvider: TestCurrentDateProvider = TestCurrentDateProvider()) { self.dateProvider = dateProvider + // The test date provider converts the duration from UInt64 to a double back and forth. + // Therefore we have rounding issues, and subtract or add the timeEpsilon. + slowestSlowFrameDuration = frozenFrameThreshold - timeEpsilon + fastestFrozenFrameDuration = frozenFrameThreshold + timeEpsilon } public var linkInvocations = Invocations() @@ -80,16 +87,15 @@ public class TestDisplayLinkWrapper: SentryDisplayLinkWrapper { } public func slowestSlowFrame() -> CFTimeInterval { - dateProvider.advance(by: frozenFrameThreshold) + dateProvider.advance(by: slowestSlowFrameDuration) call() - return frozenFrameThreshold + return slowestSlowFrameDuration } public func fastestFrozenFrame() -> CFTimeInterval { - let duration: Double = frozenFrameThreshold + timeEpsilon - dateProvider.advance(by: duration) + dateProvider.advance(by: fastestFrozenFrameDuration) call() - return duration + return fastestFrozenFrameDuration } /// There's no upper bound for a frozen frame, except maybe for the watchdog time limit. diff --git a/Sources/Sentry/SentryDependencyContainer.m b/Sources/Sentry/SentryDependencyContainer.m index ed8b36dc3d8..ab4b3dfc0d8 100644 --- a/Sources/Sentry/SentryDependencyContainer.m +++ b/Sources/Sentry/SentryDependencyContainer.m @@ -26,6 +26,7 @@ #import #import #import +#import #if SENTRY_HAS_UIKIT # import "SentryFramesTracker.h" @@ -269,7 +270,8 @@ - (SentryFramesTracker *)framesTracker if (_framesTracker == nil) { _framesTracker = [[SentryFramesTracker alloc] initWithDisplayLinkWrapper:[[SentryDisplayLinkWrapper alloc] init] - dateProvider:self.dateProvider]; + dateProvider:self.dateProvider + keepDelayedFramesDuration:SENTRY_AUTO_TRANSACTION_MAX_DURATION]; } } } diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index 568106f2a4b..137389e9a8e 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -38,7 +38,7 @@ # endif // SENTRY_TARGET_PROFILING_SUPPORTED @property (nonatomic, strong) NSMutableArray *delayedFrames; -@property (nonatomic) uint8_t delayedFrameWriteIndex; +@property (nonatomic, assign) CFTimeInterval keepDelayedFramesDuration; @end @@ -57,12 +57,14 @@ @implementation SentryFramesTracker { } - (instancetype)initWithDisplayLinkWrapper:(SentryDisplayLinkWrapper *)displayLinkWrapper - dateProvider:(SentryCurrentDateProvider *)dateProvider; + dateProvider:(SentryCurrentDateProvider *)dateProvider + keepDelayedFramesDuration:(CFTimeInterval)keepDelayedFramesDuration { if (self = [super init]) { _isRunning = NO; _displayLinkWrapper = displayLinkWrapper; _dateProvider = dateProvider; + _keepDelayedFramesDuration = keepDelayedFramesDuration; _listeners = [NSHashTable weakObjectsHashTable]; _currentFrameRate = 60; @@ -110,7 +112,6 @@ - (void)resetDelayedFramesTimeStamps expectedDuration:0 actualDuration:0]; [_delayedFrames addObject:initialFrame]; - _delayedFrameWriteIndex = 1; } - (void)start @@ -266,8 +267,7 @@ - (void)recordDelayedFrame:(uint64_t)startSystemTimestamp */ - (void)removeOldDelayedFrames { - u_int64_t transactionMaxDurationNS - = timeIntervalToNanoseconds(SENTRY_AUTO_TRANSACTION_MAX_DURATION); + u_int64_t transactionMaxDurationNS = timeIntervalToNanoseconds(_keepDelayedFramesDuration); uint64_t removeFramesBeforeSystemTimeStamp = _dateProvider.systemTime - transactionMaxDurationNS; @@ -305,10 +305,29 @@ - (CFTimeInterval)getFrameDelay:(uint64_t)startSystemTimestamp } if (endSystemTimestamp > self.dateProvider.systemTime) { - SENTRY_LOG_DEBUG(@"Not calculating frames delay endSystemTimestamp is in the future."); + SENTRY_LOG_DEBUG( + @"Not calculating frames delay because endSystemTimestamp is in the future."); return cantCalculateFrameDelay; } + NSArray *frames; + @synchronized(self.delayedFrames) { + uint64_t oldestDelayedFrameStartTimestamp = UINT64_MAX; + SentryDelayedFrame *oldestDelayedFrame = self.delayedFrames.firstObject; + if (oldestDelayedFrame != nil) { + oldestDelayedFrameStartTimestamp = oldestDelayedFrame.startSystemTimestamp; + } + + if (oldestDelayedFrameStartTimestamp > startSystemTimestamp) { + SENTRY_LOG_DEBUG(@"Not calculating frames delay because the record of delayed frames " + @"doesn't go back enough in time."); + return cantCalculateFrameDelay; + } + + // Copy as late as possible to avoid allocating unnecessary memory. + frames = self.delayedFrames.copy; + } + // Check if there is an delayed frame going on but not recorded yet. CFTimeInterval thisFrameTimestamp = self.displayLinkWrapper.timestamp; CFTimeInterval frameDuration = thisFrameTimestamp - self.previousFrameTimestamp; @@ -319,55 +338,41 @@ - (CFTimeInterval)getFrameDelay:(uint64_t)startSystemTimestamp CFTimeInterval delay = ongoingDelayedFrame; - @synchronized(self.delayedFrames) { + // Iterate in reverse order, as younger frame delays are more likely to match the queried + // period. + for (SentryDelayedFrame *frame in frames.reverseObjectEnumerator) { - // Although we use a ring buffer, and it could take a while until we get to frames within - // the time interval for which we want to return frame delay, we don't want to use a normal - // for loop with accessing the elements by index because NSFastEnumeration is faster than a - // normal for loop and in the worst case we need to iterate over all elements anyways. A - // binary search to find the first and last delayed frame in our time interval doesn't help - // either because, again, we need to iterate over all elements in the worst case. + uint64_t frameEndSystemTimeStamp + = frame.startSystemTimestamp + timeIntervalToNanoseconds(frame.actualDuration); + if (frameEndSystemTimeStamp < startSystemTimestamp) { + break; + } - uint64_t oldestDelayedFrameStartTimestamp = UINT64_MAX; + NSDate *startDate = [NSDate + dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval(startSystemTimestamp)]; + NSDate *endDate = [NSDate + dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval(endSystemTimestamp)]; - for (SentryDelayedFrame *frame in self.delayedFrames) { - if (frame.startSystemTimestamp < oldestDelayedFrameStartTimestamp) { - oldestDelayedFrameStartTimestamp = frame.startSystemTimestamp; - } - } + CFTimeInterval delayStartTime + = nanosecondsToTimeInterval(frame.startSystemTimestamp) + frame.expectedDuration; + NSDate *frameDelayStartDate = + [NSDate dateWithTimeIntervalSinceReferenceDate:delayStartTime]; - if (oldestDelayedFrameStartTimestamp > startSystemTimestamp) { - return cantCalculateFrameDelay; - } + NSDateInterval *frameDelayDateInterval = [[NSDateInterval alloc] initWithStartDate:startDate + endDate:endDate]; - for (SentryDelayedFrame *frame in self.delayedFrames) { - NSDate *startDate = - [NSDate dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval( - startSystemTimestamp)]; - NSDate *endDate = - [NSDate dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval( - endSystemTimestamp)]; - - CFTimeInterval delayStartTime - = nanosecondsToTimeInterval(frame.startSystemTimestamp) + frame.expectedDuration; - NSDate *frameDelayStartDate = - [NSDate dateWithTimeIntervalSinceReferenceDate:delayStartTime]; - - NSDateInterval *frameDelayDateInterval = - [[NSDateInterval alloc] initWithStartDate:startDate endDate:endDate]; - - // Only use the date interval for the actual delay - NSDateInterval *frameDateInterval = [[NSDateInterval alloc] - initWithStartDate:frameDelayStartDate - duration:(frame.actualDuration - frame.expectedDuration)]; - - if ([frameDelayDateInterval intersectsDateInterval:frameDateInterval]) { - NSDateInterval *intersection = - [frameDelayDateInterval intersectionWithDateInterval:frameDateInterval]; - delay = delay + intersection.duration; - } + // Only use the date interval for the actual delay + NSDateInterval *frameDateInterval = [[NSDateInterval alloc] + initWithStartDate:frameDelayStartDate + duration:(frame.actualDuration - frame.expectedDuration)]; + + if ([frameDelayDateInterval intersectsDateInterval:frameDateInterval]) { + NSDateInterval *intersection = + [frameDelayDateInterval intersectionWithDateInterval:frameDateInterval]; + delay = delay + intersection.duration; } } + return delay; } diff --git a/Sources/Sentry/include/SentryFramesTracker.h b/Sources/Sentry/include/SentryFramesTracker.h index b3a1f799408..7df3a6f2179 100644 --- a/Sources/Sentry/include/SentryFramesTracker.h +++ b/Sources/Sentry/include/SentryFramesTracker.h @@ -23,7 +23,8 @@ NS_ASSUME_NONNULL_BEGIN @interface SentryFramesTracker : NSObject - (instancetype)initWithDisplayLinkWrapper:(SentryDisplayLinkWrapper *)displayLinkWrapper - dateProvider:(SentryCurrentDateProvider *)dateProvider; + dateProvider:(SentryCurrentDateProvider *)dateProvider + keepDelayedFramesDuration:(CFTimeInterval)keepDelayedFramesDuration; @property (nonatomic, assign, readonly) SentryScreenFrames *currentFrames; @property (nonatomic, assign, readonly) BOOL isRunning; diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index 1617f4b2ede..d1108bebf58 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -10,15 +10,20 @@ class SentryFramesTrackerTests: XCTestCase { var displayLinkWrapper: TestDisplayLinkWrapper var queue: DispatchQueue var dateProvider = TestCurrentDateProvider() + let keepDelayedFramesDuration = 10.0 lazy var hub = TestHub(client: nil, andScope: nil) lazy var tracer = SentryTracer(transactionContext: TransactionContext(name: "test transaction", operation: "test operation"), hub: hub) + + let slowestSlowFrameDelay: Double init() { displayLinkWrapper = TestDisplayLinkWrapper(dateProvider: dateProvider) queue = DispatchQueue(label: "SentryFramesTrackerTests", qos: .background, attributes: [.concurrent]) + + slowestSlowFrameDelay = (displayLinkWrapper.slowestSlowFrameDuration - slowFrameThreshold(displayLinkWrapper.currentFrameRate.rawValue)) } - lazy var sut: SentryFramesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: dateProvider) + lazy var sut: SentryFramesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: dateProvider, keepDelayedFramesDuration: keepDelayedFramesDuration) } private var fixture: Fixture! @@ -146,7 +151,7 @@ class SentryFramesTrackerTests: XCTestCase { let endSystemTime = fixture.dateProvider.systemTime() - let expectedDelay = displayLink.timeEpsilon + displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + let expectedDelay = displayLink.timeEpsilon + displayLink.slowestSlowFrameDuration - slowFrameThreshold(displayLink.currentFrameRate.rawValue) let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) @@ -189,7 +194,7 @@ class SentryFramesTrackerTests: XCTestCase { let timeIntervalAfterFrameStart = 0.5 // The slow frame threshold is not included because the delayed frame started before the startDate and the rendering on time happened before the startDate. - let expectedDelay = fixture.displayLinkWrapper.frozenFrameThreshold - timeIntervalAfterFrameStart + let expectedDelay = fixture.displayLinkWrapper.slowestSlowFrameDuration - timeIntervalAfterFrameStart testFrameDelay(timeIntervalAfterFrameStart: timeIntervalAfterFrameStart, expectedDelay: expectedDelay) } @@ -206,7 +211,7 @@ class SentryFramesTrackerTests: XCTestCase { let timeIntervalAfterFrameStart = 0.0001 // The timeIntervalAfterFrameStart is not subtracted from the delay, because that's when the frame was expected to be rendered on time. - let expectedDelay = fixture.displayLinkWrapper.frozenFrameThreshold - slowFrameThreshold(fixture.displayLinkWrapper.currentFrameRate.rawValue) + let expectedDelay = fixture.displayLinkWrapper.slowestSlowFrameDuration - slowFrameThreshold(fixture.displayLinkWrapper.currentFrameRate.rawValue) testFrameDelay(timeIntervalAfterFrameStart: timeIntervalAfterFrameStart, expectedDelay: expectedDelay) } @@ -226,7 +231,7 @@ class SentryFramesTrackerTests: XCTestCase { let timeIntervalBeforeFrameEnd = 0.01 // The slow frame threshold is not included because the startDate is after the frame rendered on time. - let expectedDelay = displayLink.frozenFrameThreshold - timeIntervalAfterFrameStart - timeIntervalBeforeFrameEnd + let expectedDelay = displayLink.slowestSlowFrameDuration - timeIntervalAfterFrameStart - timeIntervalBeforeFrameEnd testFrameDelay(timeIntervalAfterFrameStart: timeIntervalAfterFrameStart, timeIntervalBeforeFrameEnd: timeIntervalBeforeFrameEnd, expectedDelay: expectedDelay) } @@ -271,7 +276,7 @@ class SentryFramesTrackerTests: XCTestCase { let timeIntervalBeforeFrameEnd = slowFrameThreshold(displayLink.currentFrameRate.rawValue) - 0.005 let endSystemTime = fixture.dateProvider.systemTime() - timeIntervalToNanoseconds(timeIntervalBeforeFrameEnd) - let expectedDelay = displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + let expectedDelay = displayLink.slowestSlowFrameDuration - slowFrameThreshold(displayLink.currentFrameRate.rawValue) let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) @@ -301,47 +306,41 @@ class SentryFramesTrackerTests: XCTestCase { expect(actualFrameDelay) == -1.0 } - func testFrameDelay_KeepAddingSlowFrames_OnlyTheCapacityFramesReturned() { - let displayLink = fixture.displayLinkWrapper + func testFrameDelay_KeepAddingSlowFrames_OnlyTheMaxDurationFramesReturned() { let sut = fixture.sut sut.start() - let startSystemTime = givenMoreDelayedFramesThanTransactionMaxDuration() + let (startSystemTime, _, expectedDelay) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) let endSystemTime = fixture.dateProvider.systemTime() - - let expectedDelay = (displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue)) let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } - func testFrameDelay_MoreThanTransactionMaxDuration_FrameInformationMissing_DelayReturned() { + func testFrameDelay_MoreThanMaxDuration_FrameInformationMissing_DelayReturned() { let sut = fixture.sut let displayLink = fixture.displayLinkWrapper sut.start() - let startSystemTime = givenMoreDelayedFramesThanTransactionMaxDuration() + let (startSystemTime, _, slowFramesDelay) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) let delayWithoutFrameRecord = 2.0 fixture.dateProvider.advance(by: delayWithoutFrameRecord) let endSystemTime = fixture.dateProvider.systemTime() - let slowFrames = sut.currentFrames.slow - let slowestSlowFrameDelay = (displayLink.frozenFrameThreshold - slowFrameThreshold(displayLink.currentFrameRate.rawValue)) - let delayNotRecorded = delayWithoutFrameRecord - slowFrameThreshold(displayLink.currentFrameRate.rawValue) - let expectedDelay = slowestSlowFrameDelay * Double(slowFrames) + delayNotRecorded + let expectedDelay = slowFramesDelay + delayNotRecorded let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } - func testFrameDelay_MoreThanTransactionMaxDuration_StartTimeTooEarly_ReturnsMinusOne() { + func testFrameDelay_MoreThanMaxDuration_StartTimeTooEarly_ReturnsMinusOne() { let sut = fixture.sut sut.start() - let startSystemTime = givenMoreDelayedFramesThanTransactionMaxDuration() + let (startSystemTime, _, _) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) let endSystemTime = fixture.dateProvider.systemTime() @@ -353,7 +352,7 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let startSystemTime = givenMoreDelayedFramesThanTransactionMaxDuration() + let (startSystemTime, _, _) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) sut.stop() @@ -367,14 +366,14 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let startSystemTimeStamp = givenMoreDelayedFramesThanTransactionMaxDuration() + let (startSystemTime, _, _) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) sut.stop() sut.start() let endSystemTime = fixture.dateProvider.systemTime() - let actualFrameDelay = sut.getFrameDelay(startSystemTimeStamp, endSystemTimestamp: endSystemTime) + let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay) == -1.0 } @@ -382,7 +381,7 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let startSystemTimeStamp = givenMoreDelayedFramesThanTransactionMaxDuration() + let (startSystemTime, _, _) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) let endSystemTime = fixture.dateProvider.systemTime() let loopSize = 1_000 @@ -392,7 +391,7 @@ class SentryFramesTrackerTests: XCTestCase { for _ in 0..= -1 @@ -400,7 +399,7 @@ class SentryFramesTrackerTests: XCTestCase { } } - _ = givenMoreDelayedFramesThanTransactionMaxDuration() + _ = givenMoreDelayedFramesThanTransactionMaxDuration(sut) wait(for: [expectation], timeout: 3.0) } @@ -449,25 +448,34 @@ class SentryFramesTrackerTests: XCTestCase { func testDealloc_CallsStop() { func sutIsDeallocatedAfterCallingMe() { - _ = SentryFramesTracker(displayLinkWrapper: fixture.displayLinkWrapper, dateProvider: fixture.dateProvider) + _ = SentryFramesTracker(displayLinkWrapper: fixture.displayLinkWrapper, dateProvider: fixture.dateProvider, keepDelayedFramesDuration: 0) } sutIsDeallocatedAfterCallingMe() XCTAssertEqual(1, fixture.displayLinkWrapper.invalidateInvocations.count) } - private func givenMoreDelayedFramesThanTransactionMaxDuration() -> UInt64 { + private func givenMoreDelayedFramesThanTransactionMaxDuration(_ framesTracker: SentryFramesTracker) -> (UInt64, UInt, Double) { let displayLink = fixture.displayLinkWrapper displayLink.call() - let transactionMaxDurationNS = timeIntervalToNanoseconds(SENTRY_AUTO_TRANSACTION_MAX_DURATION) + let slowFramesCountBeforeAddingFrames = framesTracker.currentFrames.slow + + // We have to add the delay of the slowest frame because we remove frames + // based on the endTimeStamp not the start time stamp. + let keepAddingFramesSystemTime = fixture.dateProvider.systemTime() + timeIntervalToNanoseconds(fixture.keepDelayedFramesDuration + fixture.slowestSlowFrameDelay) - while transactionMaxDurationNS >= fixture.dateProvider.systemTime() { + while fixture.dateProvider.systemTime() < keepAddingFramesSystemTime { _ = displayLink.slowestSlowFrame() } + // We have to remove 1 slow frame cause one will be older than transactionMaxDurationNS + let slowFramesCount = framesTracker.currentFrames.slow - slowFramesCountBeforeAddingFrames - 1 + + let slowFramesDelay = fixture.slowestSlowFrameDelay * Double(slowFramesCount) + // Where the second frame starts - return timeIntervalToNanoseconds(displayLink.frozenFrameThreshold) + return (timeIntervalToNanoseconds(displayLink.slowestSlowFrameDuration), slowFramesCount, slowFramesDelay) } } From 2d1eb9fd3f62ba6b3e654db12d656d8d3027df13 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 5 Dec 2023 11:02:16 +0100 Subject: [PATCH 14/33] refactor --- Sources/Sentry/SentryFramesTracker.m | 14 +++++++------- Sources/Sentry/SentrySpan.m | 2 +- Sources/Sentry/SentryTracer.m | 2 +- Sources/Sentry/include/SentryFramesTracker.h | 8 ++++++-- 4 files changed, 15 insertions(+), 11 deletions(-) diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index 137389e9a8e..ec1db5a0dde 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -288,26 +288,26 @@ - (void)removeOldDelayedFrames [self.delayedFrames removeObjectsInRange:NSMakeRange(0, i)]; } -- (CFTimeInterval)getFrameDelay:(uint64_t)startSystemTimestamp - endSystemTimestamp:(uint64_t)endSystemTimestamp +- (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp + endSystemTimestamp:(uint64_t)endSystemTimestamp { - CFTimeInterval cantCalculateFrameDelay = -1.0; + CFTimeInterval cantCalculateFrameDelayReturnValue = -1.0; if (_isRunning == NO) { SENTRY_LOG_DEBUG(@"Not calculating frames delay because frames tracker isn't running."); - return cantCalculateFrameDelay; + return cantCalculateFrameDelayReturnValue; } if (startSystemTimestamp >= endSystemTimestamp) { SENTRY_LOG_DEBUG(@"Not calculating frames delay because startSystemTimestamp is before " @"endSystemTimestamp"); - return cantCalculateFrameDelay; + return cantCalculateFrameDelayReturnValue; } if (endSystemTimestamp > self.dateProvider.systemTime) { SENTRY_LOG_DEBUG( @"Not calculating frames delay because endSystemTimestamp is in the future."); - return cantCalculateFrameDelay; + return cantCalculateFrameDelayReturnValue; } NSArray *frames; @@ -321,7 +321,7 @@ - (CFTimeInterval)getFrameDelay:(uint64_t)startSystemTimestamp if (oldestDelayedFrameStartTimestamp > startSystemTimestamp) { SENTRY_LOG_DEBUG(@"Not calculating frames delay because the record of delayed frames " @"doesn't go back enough in time."); - return cantCalculateFrameDelay; + return cantCalculateFrameDelayReturnValue; } // Copy as late as possible to avoid allocating unnecessary memory. diff --git a/Sources/Sentry/SentrySpan.m b/Sources/Sentry/SentrySpan.m index 17528bcb557..23229c87cda 100644 --- a/Sources/Sentry/SentrySpan.m +++ b/Sources/Sentry/SentrySpan.m @@ -211,7 +211,7 @@ - (void)finishWithStatus:(SentrySpanStatus)status if (_framesTracker.isRunning) { CFTimeInterval framesDelay = [_framesTracker - getFrameDelay:startSystemTime + getFramesDelay:startSystemTime endSystemTimestamp:SentryDependencyContainer.sharedInstance.dateProvider.systemTime]; if (framesDelay >= 0) { [self setDataValue:@(framesDelay) forKey:@"frames.delay"]; diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 5fb98d38c3b..b71c53f9a61 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -751,7 +751,7 @@ - (void)addMeasurements:(SentryTransaction *)transaction NSInteger frozenFrames = currentFrames.frozen - initFrozenFrames; CFTimeInterval framesDelay = [framesTracker - getFrameDelay:self.startSystemTime + getFramesDelay:self.startSystemTime endSystemTimestamp:SentryDependencyContainer.sharedInstance.dateProvider.systemTime]; if (framesDelay >= 0) { [self setMeasurement:@"frames_delay" diff --git a/Sources/Sentry/include/SentryFramesTracker.h b/Sources/Sentry/include/SentryFramesTracker.h index 7df3a6f2179..1e13b2ae63f 100644 --- a/Sources/Sentry/include/SentryFramesTracker.h +++ b/Sources/Sentry/include/SentryFramesTracker.h @@ -37,8 +37,12 @@ NS_ASSUME_NONNULL_BEGIN - (void)start; - (void)stop; -- (CFTimeInterval)getFrameDelay:(uint64_t)startSystemTimestamp - endSystemTimestamp:(uint64_t)endSystemTimestamp; +/* + * Returns the frames delay for the passed time period. If the method can't calculate the frames + * delay, it returns -1. + */ +- (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp + endSystemTimestamp:(uint64_t)endSystemTimestamp; - (void)addListener:(id)listener; From 09286641fa30254ad0d7c79654af6749243beb89 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 5 Dec 2023 11:32:49 +0100 Subject: [PATCH 15/33] add SentryDelayedFramesTracker --- Sentry.xcodeproj/project.pbxproj | 8 + Sources/Sentry/SentryDelayedFramesTracker.m | 183 ++++++++++++++++++ Sources/Sentry/SentryFramesTracker.m | 163 ++-------------- .../include/SentryDelayedFramesTracker.h | 33 ++++ .../SentryFramesTrackerTests.swift | 32 +-- 5 files changed, 259 insertions(+), 160 deletions(-) create mode 100644 Sources/Sentry/SentryDelayedFramesTracker.m create mode 100644 Sources/Sentry/include/SentryDelayedFramesTracker.h diff --git a/Sentry.xcodeproj/project.pbxproj b/Sentry.xcodeproj/project.pbxproj index a7fab6e3656..411fcb05eed 100644 --- a/Sentry.xcodeproj/project.pbxproj +++ b/Sentry.xcodeproj/project.pbxproj @@ -92,6 +92,8 @@ 62A456E52B0370E0003F19A1 /* SentryUIEventTrackerTransactionMode.m in Sources */ = {isa = PBXBuildFile; fileRef = 62A456E42B0370E0003F19A1 /* SentryUIEventTrackerTransactionMode.m */; }; 62B86CFC29F052BB008F3947 /* SentryTestLogConfig.m in Sources */ = {isa = PBXBuildFile; fileRef = 62B86CFB29F052BB008F3947 /* SentryTestLogConfig.m */; }; 62C25C862B075F4900C68CBD /* TestOptions.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62C25C852B075F4900C68CBD /* TestOptions.swift */; }; + 62C316812B1F2E93000D7031 /* SentryDelayedFramesTracker.h in Headers */ = {isa = PBXBuildFile; fileRef = 62C316802B1F2E93000D7031 /* SentryDelayedFramesTracker.h */; }; + 62C316832B1F2EA1000D7031 /* SentryDelayedFramesTracker.m in Sources */ = {isa = PBXBuildFile; fileRef = 62C316822B1F2EA1000D7031 /* SentryDelayedFramesTracker.m */; }; 62E081A929ED4260000F69FC /* SentryBreadcrumbDelegate.h in Headers */ = {isa = PBXBuildFile; fileRef = 62E081A829ED4260000F69FC /* SentryBreadcrumbDelegate.h */; }; 62E081AB29ED4322000F69FC /* SentryBreadcrumbTestDelegate.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62E081AA29ED4322000F69FC /* SentryBreadcrumbTestDelegate.swift */; }; 62F226B729A37C120038080D /* SentryBooleanSerialization.m in Sources */ = {isa = PBXBuildFile; fileRef = 62F226B629A37C120038080D /* SentryBooleanSerialization.m */; }; @@ -981,6 +983,8 @@ 62A456E42B0370E0003F19A1 /* SentryUIEventTrackerTransactionMode.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryUIEventTrackerTransactionMode.m; sourceTree = ""; }; 62B86CFB29F052BB008F3947 /* SentryTestLogConfig.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryTestLogConfig.m; sourceTree = ""; }; 62C25C852B075F4900C68CBD /* TestOptions.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = TestOptions.swift; sourceTree = ""; }; + 62C316802B1F2E93000D7031 /* SentryDelayedFramesTracker.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryDelayedFramesTracker.h; path = include/SentryDelayedFramesTracker.h; sourceTree = ""; }; + 62C316822B1F2EA1000D7031 /* SentryDelayedFramesTracker.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryDelayedFramesTracker.m; sourceTree = ""; }; 62E081A829ED4260000F69FC /* SentryBreadcrumbDelegate.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryBreadcrumbDelegate.h; path = include/SentryBreadcrumbDelegate.h; sourceTree = ""; }; 62E081AA29ED4322000F69FC /* SentryBreadcrumbTestDelegate.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryBreadcrumbTestDelegate.swift; sourceTree = ""; }; 62F226B629A37C120038080D /* SentryBooleanSerialization.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryBooleanSerialization.m; sourceTree = ""; }; @@ -2908,6 +2912,8 @@ 7B7A599626B692F00060A676 /* SentryScreenFrames.m */, 62862B1B2B1DDBC8009B16E3 /* SentryDelayedFrame.h */, 62862B1D2B1DDC35009B16E3 /* SentryDelayedFrame.m */, + 62C316802B1F2E93000D7031 /* SentryDelayedFramesTracker.h */, + 62C316822B1F2EA1000D7031 /* SentryDelayedFramesTracker.m */, ); name = FramesTracking; sourceTree = ""; @@ -3585,6 +3591,7 @@ 63FE718720DA4C1100CDBAE8 /* SentryCrashReportVersion.h in Headers */, 0A56DA5F28ABA01B00C400D5 /* SentryTransactionContext+Private.h in Headers */, 8E7C98312693E1CC00E6336C /* SentryTraceHeader.h in Headers */, + 62C316812B1F2E93000D7031 /* SentryDelayedFramesTracker.h in Headers */, 7BBD18912449BE9000427C76 /* SentryDefaultRateLimits.h in Headers */, 7B8713AE26415ADF006D6004 /* SentryAppStartTrackingIntegration.h in Headers */, 7B7D873224864BB900D2ECFF /* SentryCrashMachineContextWrapper.h in Headers */, @@ -4148,6 +4155,7 @@ 03F84D3827DD4191008FE43F /* SentryBacktrace.cpp in Sources */, 63FE712720DA4C1000CDBAE8 /* SentryCrashThread.c in Sources */, 7B127B0F27CF6F4700A71ED2 /* SentryANRTrackingIntegration.m in Sources */, + 62C316832B1F2EA1000D7031 /* SentryDelayedFramesTracker.m in Sources */, D8BFE37329A3782F002E73F3 /* SentryTimeToDisplayTracker.m in Sources */, 15360CCF2432777500112302 /* SentrySessionTracker.m in Sources */, 6334314320AD9AE40077E581 /* SentryMechanism.m in Sources */, diff --git a/Sources/Sentry/SentryDelayedFramesTracker.m b/Sources/Sentry/SentryDelayedFramesTracker.m new file mode 100644 index 00000000000..8c84949649b --- /dev/null +++ b/Sources/Sentry/SentryDelayedFramesTracker.m @@ -0,0 +1,183 @@ +#import "SentryDelayedFramesTracker.h" + +#if SENTRY_HAS_UIKIT + +# import "SentryCurrentDateProvider.h" +# import "SentryDelayedFrame.h" +# import "SentryLog.h" +# import "SentryTime.h" + +NS_ASSUME_NONNULL_BEGIN + +@interface +SentryDelayedFramesTracker () + +@property (nonatomic, assign) CFTimeInterval keepDelayedFramesDuration; +@property (nonatomic, strong, readonly) SentryCurrentDateProvider *dateProvider; +@property (nonatomic, strong) NSMutableArray *delayedFrames; + +@end + +@implementation SentryDelayedFramesTracker + +- (instancetype)initWithKeepDelayedFramesDuration:(CFTimeInterval)keepDelayedFramesDuration + dateProvider:(SentryCurrentDateProvider *)dateProvider +{ + if (self = [super init]) { + _keepDelayedFramesDuration = keepDelayedFramesDuration; + _dateProvider = dateProvider; + [self resetDelayedFramesTimeStamps]; + } + return self; +} + +- (void)resetDelayedFramesTimeStamps +{ + _delayedFrames = [NSMutableArray array]; + SentryDelayedFrame *initialFrame = + [[SentryDelayedFrame alloc] initWithStartTimestamp:[self.dateProvider systemTime] + expectedDuration:0 + actualDuration:0]; + [_delayedFrames addObject:initialFrame]; +} + +- (void)recordDelayedFrame:(uint64_t)startSystemTimestamp + expectedDuration:(CFTimeInterval)expectedDuration + actualDuration:(CFTimeInterval)actualDuration +{ + @synchronized(self.delayedFrames) { + [self removeOldDelayedFrames]; + + SENTRY_LOG_DEBUG(@"FrameDelay: Record expected:%f ms actual %f ms", expectedDuration * 1000, + actualDuration * 1000); + SentryDelayedFrame *delayedFrame = + [[SentryDelayedFrame alloc] initWithStartTimestamp:startSystemTimestamp + expectedDuration:expectedDuration + actualDuration:actualDuration]; + [self.delayedFrames addObject:delayedFrame]; + } +} + +/** + * Removes delayed frame that are older than current time minus `keepDelayedFramesDuration`. + * @note Make sure to call this in a @synchronized block. + */ +- (void)removeOldDelayedFrames +{ + u_int64_t transactionMaxDurationNS = timeIntervalToNanoseconds(_keepDelayedFramesDuration); + + uint64_t removeFramesBeforeSystemTimeStamp + = _dateProvider.systemTime - transactionMaxDurationNS; + if (_dateProvider.systemTime < transactionMaxDurationNS) { + removeFramesBeforeSystemTimeStamp = 0; + } + + NSInteger i = 0; + for (SentryDelayedFrame *frame in self.delayedFrames) { + uint64_t frameEndSystemTimeStamp + = frame.startSystemTimestamp + timeIntervalToNanoseconds(frame.actualDuration); + if (frameEndSystemTimeStamp < removeFramesBeforeSystemTimeStamp) { + i++; + } else { + break; + } + } + [self.delayedFrames removeObjectsInRange:NSMakeRange(0, i)]; +} + +- (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp + endSystemTimestamp:(uint64_t)endSystemTimestamp + isRunning:(BOOL)isRunning + thisFrameTimestamp:(CFTimeInterval)thisFrameTimestamp + previousFrameTimestamp:(CFTimeInterval)previousFrameTimestamp + slowFrameThreshold:(CFTimeInterval)slowFrameThreshold +{ + CFTimeInterval cantCalculateFrameDelayReturnValue = -1.0; + + if (isRunning == NO) { + SENTRY_LOG_DEBUG(@"Not calculating frames delay because frames tracker isn't running."); + return cantCalculateFrameDelayReturnValue; + } + + if (startSystemTimestamp >= endSystemTimestamp) { + SENTRY_LOG_DEBUG(@"Not calculating frames delay because startSystemTimestamp is before " + @"endSystemTimestamp"); + return cantCalculateFrameDelayReturnValue; + } + + if (endSystemTimestamp > self.dateProvider.systemTime) { + SENTRY_LOG_DEBUG( + @"Not calculating frames delay because endSystemTimestamp is in the future."); + return cantCalculateFrameDelayReturnValue; + } + + NSArray *frames; + @synchronized(self.delayedFrames) { + uint64_t oldestDelayedFrameStartTimestamp = UINT64_MAX; + SentryDelayedFrame *oldestDelayedFrame = self.delayedFrames.firstObject; + if (oldestDelayedFrame != nil) { + oldestDelayedFrameStartTimestamp = oldestDelayedFrame.startSystemTimestamp; + } + + if (oldestDelayedFrameStartTimestamp > startSystemTimestamp) { + SENTRY_LOG_DEBUG(@"Not calculating frames delay because the record of delayed frames " + @"doesn't go back enough in time."); + return cantCalculateFrameDelayReturnValue; + } + + // Copy as late as possible to avoid allocating unnecessary memory. + frames = self.delayedFrames.copy; + } + + // 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; + } + + CFTimeInterval delay = ongoingDelayedFrame; + + // Iterate in reverse order, as younger frame delays are more likely to match the queried + // period. + for (SentryDelayedFrame *frame in frames.reverseObjectEnumerator) { + + uint64_t frameEndSystemTimeStamp + = frame.startSystemTimestamp + timeIntervalToNanoseconds(frame.actualDuration); + if (frameEndSystemTimeStamp < startSystemTimestamp) { + break; + } + + NSDate *startDate = [NSDate + dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval(startSystemTimestamp)]; + NSDate *endDate = [NSDate + dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval(endSystemTimestamp)]; + + CFTimeInterval delayStartTime + = nanosecondsToTimeInterval(frame.startSystemTimestamp) + frame.expectedDuration; + NSDate *frameDelayStartDate = + [NSDate dateWithTimeIntervalSinceReferenceDate:delayStartTime]; + + NSDateInterval *frameDelayDateInterval = [[NSDateInterval alloc] initWithStartDate:startDate + endDate:endDate]; + + // Only use the date interval for the actual delay + NSDateInterval *frameDateInterval = [[NSDateInterval alloc] + initWithStartDate:frameDelayStartDate + duration:(frame.actualDuration - frame.expectedDuration)]; + + if ([frameDelayDateInterval intersectsDateInterval:frameDateInterval]) { + NSDateInterval *intersection = + [frameDelayDateInterval intersectionWithDateInterval:frameDateInterval]; + delay = delay + intersection.duration; + } + } + + return delay; +} + +@end + +NS_ASSUME_NONNULL_END + +#endif // SENTRY_HAS_UIKIT diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index ec1db5a0dde..3cd7873b591 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -5,6 +5,7 @@ # import "SentryCompiler.h" # import "SentryCurrentDateProvider.h" # import "SentryDelayedFrame.h" +# import "SentryDelayedFramesTracker.h" # import "SentryDisplayLinkWrapper.h" # import "SentryLog.h" # import "SentryProfiler.h" @@ -37,8 +38,7 @@ @property (nonatomic, readwrite) SentryMutableFrameInfoTimeSeries *frameRateTimestamps; # endif // SENTRY_TARGET_PROFILING_SUPPORTED -@property (nonatomic, strong) NSMutableArray *delayedFrames; -@property (nonatomic, assign) CFTimeInterval keepDelayedFramesDuration; +@property (nonatomic, strong) SentryDelayedFramesTracker *delayedFramesTracker; @end @@ -64,7 +64,10 @@ - (instancetype)initWithDisplayLinkWrapper:(SentryDisplayLinkWrapper *)displayLi _isRunning = NO; _displayLinkWrapper = displayLinkWrapper; _dateProvider = dateProvider; - _keepDelayedFramesDuration = keepDelayedFramesDuration; + _delayedFramesTracker = [[SentryDelayedFramesTracker alloc] + initWithKeepDelayedFramesDuration:keepDelayedFramesDuration + dateProvider:dateProvider]; + _listeners = [NSHashTable weakObjectsHashTable]; _currentFrameRate = 60; @@ -92,7 +95,7 @@ - (void)resetFrames [self resetProfilingTimestamps]; # endif // SENTRY_TARGET_PROFILING_SUPPORTED - [self resetDelayedFramesTimeStamps]; + [self.delayedFramesTracker resetDelayedFramesTimeStamps]; } # if SENTRY_TARGET_PROFILING_SUPPORTED @@ -104,16 +107,6 @@ - (void)resetProfilingTimestamps } # endif // SENTRY_TARGET_PROFILING_SUPPORTED -- (void)resetDelayedFramesTimeStamps -{ - _delayedFrames = [NSMutableArray array]; - SentryDelayedFrame *initialFrame = - [[SentryDelayedFrame alloc] initWithStartTimestamp:[self.dateProvider systemTime] - expectedDuration:0 - actualDuration:0]; - [_delayedFrames addObject:initialFrame]; -} - - (void)start { if (_isRunning) { @@ -191,9 +184,9 @@ - (void)displayLinkCallback } if (frameDuration > slowFrameThreshold(_currentFrameRate)) { - [self recordDelayedFrame:self.previousFrameSystemTimestamp - expectedDuration:slowFrameThreshold(_currentFrameRate) - actualDuration:frameDuration]; + [self.delayedFramesTracker recordDelayedFrame:self.previousFrameSystemTimestamp + expectedDuration:slowFrameThreshold(_currentFrameRate) + actualDuration:frameDuration]; } _totalFrames++; @@ -243,137 +236,15 @@ - (SentryScreenFrames *)currentFrames # endif // SENTRY_TARGET_PROFILING_SUPPORTED } -- (void)recordDelayedFrame:(uint64_t)startSystemTimestamp - expectedDuration:(CFTimeInterval)expectedDuration - actualDuration:(CFTimeInterval)actualDuration -{ - @synchronized(self.delayedFrames) { - [self removeOldDelayedFrames]; - - SENTRY_LOG_DEBUG(@"FrameDelay: Record expected:%f ms actual %f ms", expectedDuration * 1000, - actualDuration * 1000); - SentryDelayedFrame *delayedFrame = - [[SentryDelayedFrame alloc] initWithStartTimestamp:startSystemTimestamp - expectedDuration:expectedDuration - actualDuration:actualDuration]; - [self.delayedFrames addObject:delayedFrame]; - } -} - -/** - * Removes delayed frame that are older than current time minus - * SENTRY_AUTO_TRANSACTION_MAX_DURATION. - * @note Make sure to call this in a @synchronized block. - */ -- (void)removeOldDelayedFrames -{ - u_int64_t transactionMaxDurationNS = timeIntervalToNanoseconds(_keepDelayedFramesDuration); - - uint64_t removeFramesBeforeSystemTimeStamp - = _dateProvider.systemTime - transactionMaxDurationNS; - if (_dateProvider.systemTime < transactionMaxDurationNS) { - removeFramesBeforeSystemTimeStamp = 0; - } - - NSInteger i = 0; - for (SentryDelayedFrame *frame in self.delayedFrames) { - uint64_t frameEndSystemTimeStamp - = frame.startSystemTimestamp + timeIntervalToNanoseconds(frame.actualDuration); - if (frameEndSystemTimeStamp < removeFramesBeforeSystemTimeStamp) { - i++; - } else { - break; - } - } - [self.delayedFrames removeObjectsInRange:NSMakeRange(0, i)]; -} - - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp endSystemTimestamp:(uint64_t)endSystemTimestamp { - CFTimeInterval cantCalculateFrameDelayReturnValue = -1.0; - - if (_isRunning == NO) { - SENTRY_LOG_DEBUG(@"Not calculating frames delay because frames tracker isn't running."); - return cantCalculateFrameDelayReturnValue; - } - - if (startSystemTimestamp >= endSystemTimestamp) { - SENTRY_LOG_DEBUG(@"Not calculating frames delay because startSystemTimestamp is before " - @"endSystemTimestamp"); - return cantCalculateFrameDelayReturnValue; - } - - if (endSystemTimestamp > self.dateProvider.systemTime) { - SENTRY_LOG_DEBUG( - @"Not calculating frames delay because endSystemTimestamp is in the future."); - return cantCalculateFrameDelayReturnValue; - } - - NSArray *frames; - @synchronized(self.delayedFrames) { - uint64_t oldestDelayedFrameStartTimestamp = UINT64_MAX; - SentryDelayedFrame *oldestDelayedFrame = self.delayedFrames.firstObject; - if (oldestDelayedFrame != nil) { - oldestDelayedFrameStartTimestamp = oldestDelayedFrame.startSystemTimestamp; - } - - if (oldestDelayedFrameStartTimestamp > startSystemTimestamp) { - SENTRY_LOG_DEBUG(@"Not calculating frames delay because the record of delayed frames " - @"doesn't go back enough in time."); - return cantCalculateFrameDelayReturnValue; - } - - // Copy as late as possible to avoid allocating unnecessary memory. - frames = self.delayedFrames.copy; - } - - // Check if there is an delayed frame going on but not recorded yet. - CFTimeInterval thisFrameTimestamp = self.displayLinkWrapper.timestamp; - CFTimeInterval frameDuration = thisFrameTimestamp - self.previousFrameTimestamp; - CFTimeInterval ongoingDelayedFrame = 0.0; - if (frameDuration > slowFrameThreshold(_currentFrameRate)) { - ongoingDelayedFrame = frameDuration - slowFrameThreshold(_currentFrameRate); - } - - CFTimeInterval delay = ongoingDelayedFrame; - - // Iterate in reverse order, as younger frame delays are more likely to match the queried - // period. - for (SentryDelayedFrame *frame in frames.reverseObjectEnumerator) { - - uint64_t frameEndSystemTimeStamp - = frame.startSystemTimestamp + timeIntervalToNanoseconds(frame.actualDuration); - if (frameEndSystemTimeStamp < startSystemTimestamp) { - break; - } - - NSDate *startDate = [NSDate - dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval(startSystemTimestamp)]; - NSDate *endDate = [NSDate - dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval(endSystemTimestamp)]; - - CFTimeInterval delayStartTime - = nanosecondsToTimeInterval(frame.startSystemTimestamp) + frame.expectedDuration; - NSDate *frameDelayStartDate = - [NSDate dateWithTimeIntervalSinceReferenceDate:delayStartTime]; - - NSDateInterval *frameDelayDateInterval = [[NSDateInterval alloc] initWithStartDate:startDate - endDate:endDate]; - - // Only use the date interval for the actual delay - NSDateInterval *frameDateInterval = [[NSDateInterval alloc] - initWithStartDate:frameDelayStartDate - duration:(frame.actualDuration - frame.expectedDuration)]; - - if ([frameDelayDateInterval intersectsDateInterval:frameDateInterval]) { - NSDateInterval *intersection = - [frameDelayDateInterval intersectionWithDateInterval:frameDateInterval]; - delay = delay + intersection.duration; - } - } - - return delay; + return [self.delayedFramesTracker getFramesDelay:startSystemTimestamp + endSystemTimestamp:endSystemTimestamp + isRunning:_isRunning + thisFrameTimestamp:self.displayLinkWrapper.timestamp + previousFrameTimestamp:self.previousFrameTimestamp + slowFrameThreshold:slowFrameThreshold(_currentFrameRate)]; } - (void)addListener:(id)listener @@ -395,7 +266,7 @@ - (void)stop { _isRunning = NO; [self.displayLinkWrapper invalidate]; - [self resetDelayedFramesTimeStamps]; + [self.delayedFramesTracker resetDelayedFramesTimeStamps]; } - (void)dealloc diff --git a/Sources/Sentry/include/SentryDelayedFramesTracker.h b/Sources/Sentry/include/SentryDelayedFramesTracker.h new file mode 100644 index 00000000000..f355f2a945d --- /dev/null +++ b/Sources/Sentry/include/SentryDelayedFramesTracker.h @@ -0,0 +1,33 @@ +#import "SentryDefines.h" + +#if SENTRY_HAS_UIKIT + +@class SentryDisplayLinkWrapper; +@class SentryCurrentDateProvider; + +NS_ASSUME_NONNULL_BEGIN + +@interface SentryDelayedFramesTracker : NSObject +SENTRY_NO_INIT + +- (instancetype)initWithKeepDelayedFramesDuration:(CFTimeInterval)keepDelayedFramesDuration + dateProvider:(SentryCurrentDateProvider *)dateProvider; + +- (void)resetDelayedFramesTimeStamps; + +- (void)recordDelayedFrame:(uint64_t)startSystemTimestamp + expectedDuration:(CFTimeInterval)expectedDuration + actualDuration:(CFTimeInterval)actualDuration; + +- (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp + endSystemTimestamp:(uint64_t)endSystemTimestamp + isRunning:(BOOL)isRunning + thisFrameTimestamp:(CFTimeInterval)thisFrameTimestamp + previousFrameTimestamp:(CFTimeInterval)previousFrameTimestamp + slowFrameThreshold:(CFTimeInterval)slowFrameThreshold; + +@end + +NS_ASSUME_NONNULL_END + +#endif // SENTRY_HAS_UIKIT diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index d1108bebf58..e20173e088d 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -153,7 +153,7 @@ class SentryFramesTrackerTests: XCTestCase { let expectedDelay = displayLink.timeEpsilon + displayLink.slowestSlowFrameDuration - slowFrameThreshold(displayLink.currentFrameRate.rawValue) - let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } @@ -180,7 +180,7 @@ class SentryFramesTrackerTests: XCTestCase { let expectedDelay = delayWithoutFrameRecord - slowFrameThreshold(displayLink.currentFrameRate.rawValue) - let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } @@ -250,7 +250,7 @@ class SentryFramesTrackerTests: XCTestCase { let startSystemTime = slowFrameStartSystemTime + timeIntervalToNanoseconds(timeIntervalAfterFrameStart) - let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } @@ -278,7 +278,7 @@ class SentryFramesTrackerTests: XCTestCase { let expectedDelay = displayLink.slowestSlowFrameDuration - slowFrameThreshold(displayLink.currentFrameRate.rawValue) - let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } @@ -290,7 +290,7 @@ class SentryFramesTrackerTests: XCTestCase { displayLink.call() _ = displayLink.slowestSlowFrame() - let actualFrameDelay = sut.getFrameDelay(1, endSystemTimestamp: 0) + let actualFrameDelay = sut.getFramesDelay(1, endSystemTimestamp: 0) expect(actualFrameDelay) == -1.0 } @@ -302,7 +302,7 @@ class SentryFramesTrackerTests: XCTestCase { displayLink.call() _ = displayLink.slowestSlowFrame() - let actualFrameDelay = sut.getFrameDelay(0, endSystemTimestamp: UInt64.max) + let actualFrameDelay = sut.getFramesDelay(0, endSystemTimestamp: UInt64.max) expect(actualFrameDelay) == -1.0 } @@ -314,7 +314,7 @@ class SentryFramesTrackerTests: XCTestCase { let endSystemTime = fixture.dateProvider.systemTime() - let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } @@ -332,7 +332,7 @@ class SentryFramesTrackerTests: XCTestCase { let delayNotRecorded = delayWithoutFrameRecord - slowFrameThreshold(displayLink.currentFrameRate.rawValue) let expectedDelay = slowFramesDelay + delayNotRecorded - let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) } @@ -344,7 +344,7 @@ class SentryFramesTrackerTests: XCTestCase { let endSystemTime = fixture.dateProvider.systemTime() - let actualFrameDelay = sut.getFrameDelay(startSystemTime - 1, endSystemTimestamp: endSystemTime) + let actualFrameDelay = sut.getFramesDelay(startSystemTime - 1, endSystemTimestamp: endSystemTime) expect(actualFrameDelay).to(beCloseTo(-1, within: 0.0001), description: "startSystemTimeStamp starts one nanosecond before the oldest slow frame. Therefore the frame delay can't be calculated and should me 0.") } @@ -352,13 +352,17 @@ class SentryFramesTrackerTests: XCTestCase { let sut = fixture.sut sut.start() - let (startSystemTime, _, _) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) + let startSystemTime = fixture.dateProvider.systemTime() - sut.stop() + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() let endSystemTime = fixture.dateProvider.systemTime() - let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) + sut.stop() + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay) == -1.0 } @@ -373,7 +377,7 @@ class SentryFramesTrackerTests: XCTestCase { let endSystemTime = fixture.dateProvider.systemTime() - let actualFrameDelay = sut.getFrameDelay(startSystemTime, endSystemTimestamp: endSystemTime) + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) expect(actualFrameDelay) == -1.0 } @@ -391,7 +395,7 @@ class SentryFramesTrackerTests: XCTestCase { for _ in 0..= -1 From 2a3ca45486453a5b669c70054fa0153f9fa19c6c Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Tue, 5 Dec 2023 11:45:31 +0100 Subject: [PATCH 16/33] more cleanup --- Sources/Sentry/SentryDelayedFramesTracker.m | 20 +++++++++++--------- 1 file changed, 11 insertions(+), 9 deletions(-) diff --git a/Sources/Sentry/SentryDelayedFramesTracker.m b/Sources/Sentry/SentryDelayedFramesTracker.m index 8c84949649b..e918e8659e5 100644 --- a/Sources/Sentry/SentryDelayedFramesTracker.m +++ b/Sources/Sentry/SentryDelayedFramesTracker.m @@ -48,8 +48,6 @@ - (void)recordDelayedFrame:(uint64_t)startSystemTimestamp @synchronized(self.delayedFrames) { [self removeOldDelayedFrames]; - SENTRY_LOG_DEBUG(@"FrameDelay: Record expected:%f ms actual %f ms", expectedDuration * 1000, - actualDuration * 1000); SentryDelayedFrame *delayedFrame = [[SentryDelayedFrame alloc] initWithStartTimestamp:startSystemTimestamp expectedDuration:expectedDuration @@ -148,27 +146,31 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp break; } + // We need to calculate the intersections of the queried TimestampInterval + // (startSystemTimestamp - endSystemTimestamp) with the recorded frame delays. Doing that + // with NSDateInterval makes things easier. Therefore, we convert the system timestamps to + // NSDate objects, although they don't represent the correct dates. We only need to know how + // long the intersections are to calculate the frame delay and not precisely when. + NSDate *startDate = [NSDate dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval(startSystemTimestamp)]; NSDate *endDate = [NSDate dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval(endSystemTimestamp)]; + NSDateInterval *queryDateInterval = [[NSDateInterval alloc] initWithStartDate:startDate + endDate:endDate]; CFTimeInterval delayStartTime = nanosecondsToTimeInterval(frame.startSystemTimestamp) + frame.expectedDuration; NSDate *frameDelayStartDate = [NSDate dateWithTimeIntervalSinceReferenceDate:delayStartTime]; - NSDateInterval *frameDelayDateInterval = [[NSDateInterval alloc] initWithStartDate:startDate - endDate:endDate]; - - // Only use the date interval for the actual delay - NSDateInterval *frameDateInterval = [[NSDateInterval alloc] + NSDateInterval *frameDelayDateInterval = [[NSDateInterval alloc] initWithStartDate:frameDelayStartDate duration:(frame.actualDuration - frame.expectedDuration)]; - if ([frameDelayDateInterval intersectsDateInterval:frameDateInterval]) { + if ([queryDateInterval intersectsDateInterval:frameDelayDateInterval]) { NSDateInterval *intersection = - [frameDelayDateInterval intersectionWithDateInterval:frameDateInterval]; + [queryDateInterval intersectionWithDateInterval:frameDelayDateInterval]; delay = delay + intersection.duration; } } From add473ffbaf0d0b2f43769b6b70de63b02137df0 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 7 Dec 2023 09:32:58 +0100 Subject: [PATCH 17/33] test build failure fixes --- SentryTestUtils/TestDisplayLinkWrapper.swift | 4 ++-- Sources/Sentry/SentrySpan.m | 1 - Sources/Sentry/SentryTime.mm | 7 ------- .../UIViewController/SentryTimeToDisplayTrackerTest.swift | 2 +- Tests/SentryTests/Transaction/SentrySpanTests.swift | 2 +- 5 files changed, 4 insertions(+), 12 deletions(-) diff --git a/SentryTestUtils/TestDisplayLinkWrapper.swift b/SentryTestUtils/TestDisplayLinkWrapper.swift index 835c567d0cf..5f1016990e0 100644 --- a/SentryTestUtils/TestDisplayLinkWrapper.swift +++ b/SentryTestUtils/TestDisplayLinkWrapper.swift @@ -23,8 +23,8 @@ public class TestDisplayLinkWrapper: SentryDisplayLinkWrapper { public var currentFrameRate: FrameRate = .low private let frozenFrameThreshold = 0.7 - private let slowestSlowFrameDuration: Double - private let fastestFrozenFrameDuration: Double + public let slowestSlowFrameDuration: Double + public let fastestFrozenFrameDuration: Double public var dateProvider: TestCurrentDateProvider /// The smallest magnitude of time that is significant to how frames are classified as normal/slow/frozen. diff --git a/Sources/Sentry/SentrySpan.m b/Sources/Sentry/SentrySpan.m index 7a9131c4ee6..a9ac7bb1221 100644 --- a/Sources/Sentry/SentrySpan.m +++ b/Sources/Sentry/SentrySpan.m @@ -50,7 +50,6 @@ - (instancetype)initWithContext:(SentrySpanContext *)context { if (self = [super init]) { self.startTimestamp = [SentryDependencyContainer.sharedInstance.dateProvider date]; - startSystemTime = SentryDependencyContainer.sharedInstance.dateProvider.systemTime; _data = [[NSMutableDictionary alloc] init]; SentryCrashThread currentThread = sentrycrashthread_self(); diff --git a/Sources/Sentry/SentryTime.mm b/Sources/Sentry/SentryTime.mm index d3b147e6c1c..d003e68c422 100644 --- a/Sources/Sentry/SentryTime.mm +++ b/Sources/Sentry/SentryTime.mm @@ -21,13 +21,6 @@ return (double)nanoseconds / NSEC_PER_SEC; } -double -nanosecondsToTimeInterval(uint64_t nanoseconds) -{ - NSCAssert(nanoseconds <= UINT64_MAX, @"Nanoseconds must not exceed UINT64_MAX"); - return (double)nanoseconds / 1e9; -} - uint64_t getAbsoluteTime(void) { diff --git a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift index 15523f0493d..f0bb2434c3f 100644 --- a/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift +++ b/Tests/SentryTests/Integrations/Performance/UIViewController/SentryTimeToDisplayTrackerTest.swift @@ -15,7 +15,7 @@ class SentryTimeToDisplayTrackerTest: XCTestCase { var framesTracker: SentryFramesTracker init() { - framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper) + framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: dateProvider, keepDelayedFramesDuration: 0) SentryDependencyContainer.sharedInstance().framesTracker = framesTracker framesTracker.start() } diff --git a/Tests/SentryTests/Transaction/SentrySpanTests.swift b/Tests/SentryTests/Transaction/SentrySpanTests.swift index 23a49998353..b6e71b1d328 100644 --- a/Tests/SentryTests/Transaction/SentrySpanTests.swift +++ b/Tests/SentryTests/Transaction/SentrySpanTests.swift @@ -555,7 +555,7 @@ class SentrySpanTests: XCTestCase { private func givenFramesTracker() -> (TestDisplayLinkWrapper, SentryFramesTracker) { let displayLinkWrapper = TestDisplayLinkWrapper() - let framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper) + let framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: TestCurrentDateProvider(), keepDelayedFramesDuration: 0) framesTracker.start() displayLinkWrapper.call() From 10df07208c0748fb94221dddd54f93eb4a71407d Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 7 Dec 2023 09:36:00 +0100 Subject: [PATCH 18/33] remove unwanted span changes --- Sources/Sentry/SentrySpan.m | 11 ----------- 1 file changed, 11 deletions(-) diff --git a/Sources/Sentry/SentrySpan.m b/Sources/Sentry/SentrySpan.m index a9ac7bb1221..8ea1cac2b50 100644 --- a/Sources/Sentry/SentrySpan.m +++ b/Sources/Sentry/SentrySpan.m @@ -57,17 +57,6 @@ - (instancetype)initWithContext:(SentrySpanContext *)context if ([NSThread isMainThread]) { _data[SPAN_DATA_THREAD_NAME] = @"main"; - -#if SENTRY_HAS_UIKIT - // Only track frames if running on main thread. - _framesTracker = framesTracker; - if (_framesTracker.isRunning) { - SentryScreenFrames *currentFrames = _framesTracker.currentFrames; - initTotalFrames = currentFrames.total; - initSlowFrames = currentFrames.slow; - initFrozenFrames = currentFrames.frozen; - } -#endif // SENTRY_HAS_UIKIT } else { _data[SPAN_DATA_THREAD_NAME] = [SentryDependencyContainer.sharedInstance.threadInspector getThreadName:currentThread]; From c26121a2ebffad82c87522064b5c7b53d0bb6847 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 7 Dec 2023 10:10:27 +0100 Subject: [PATCH 19/33] use binary search for deleting items --- Sources/Sentry/SentryDelayedFramesTracker.m | 20 +++++++++++++------- 1 file changed, 13 insertions(+), 7 deletions(-) diff --git a/Sources/Sentry/SentryDelayedFramesTracker.m b/Sources/Sentry/SentryDelayedFramesTracker.m index e918e8659e5..e18d9eac1f0 100644 --- a/Sources/Sentry/SentryDelayedFramesTracker.m +++ b/Sources/Sentry/SentryDelayedFramesTracker.m @@ -70,17 +70,23 @@ - (void)removeOldDelayedFrames removeFramesBeforeSystemTimeStamp = 0; } - NSInteger i = 0; - for (SentryDelayedFrame *frame in self.delayedFrames) { + NSUInteger left = 0; + NSUInteger right = self.delayedFrames.count; + + while (left < right) { + NSUInteger mid = (left + right) / 2; + SentryDelayedFrame *midFrame = self.delayedFrames[mid]; + uint64_t frameEndSystemTimeStamp - = frame.startSystemTimestamp + timeIntervalToNanoseconds(frame.actualDuration); - if (frameEndSystemTimeStamp < removeFramesBeforeSystemTimeStamp) { - i++; + = midFrame.startSystemTimestamp + timeIntervalToNanoseconds(midFrame.actualDuration); + if (frameEndSystemTimeStamp >= removeFramesBeforeSystemTimeStamp) { + right = mid; } else { - break; + left = mid + 1; } } - [self.delayedFrames removeObjectsInRange:NSMakeRange(0, i)]; + + [self.delayedFrames removeObjectsInRange:NSMakeRange(0, left)]; } - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp From 34136a6dd5a1efe3b5dbee1d93764affacd41a5a Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 7 Dec 2023 10:35:07 +0100 Subject: [PATCH 20/33] add tracertests --- Sources/Sentry/SentryTracer.m | 4 +-- .../Transaction/SentryTracerTests.swift | 31 ++++++++++++------- 2 files changed, 21 insertions(+), 14 deletions(-) diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index b71c53f9a61..95ff49d1b70 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -754,9 +754,7 @@ - (void)addMeasurements:(SentryTransaction *)transaction getFramesDelay:self.startSystemTime endSystemTimestamp:SentryDependencyContainer.sharedInstance.dateProvider.systemTime]; if (framesDelay >= 0) { - [self setMeasurement:@"frames_delay" - value:@(framesDelay) - unit:SentryMeasurementUnitDuration.second]; + [self setMeasurement:@"frames_delay" value:@(framesDelay)]; } if (sentryShouldAddSlowFrozenFramesData(totalFrames, slowFrames, frozenFrames)) { diff --git a/Tests/SentryTests/Transaction/SentryTracerTests.swift b/Tests/SentryTests/Transaction/SentryTracerTests.swift index 93efca9723f..c1f5cae15b0 100644 --- a/Tests/SentryTests/Transaction/SentryTracerTests.swift +++ b/Tests/SentryTests/Transaction/SentryTracerTests.swift @@ -1,3 +1,4 @@ +import Nimble import SentryTestUtils import XCTest @@ -62,7 +63,7 @@ class SentryTracerTests: XCTestCase { hub = TestHub(client: client, andScope: scope) #if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) - displayLinkWrapper = TestDisplayLinkWrapper() + displayLinkWrapper = TestDisplayLinkWrapper(dateProvider: currentDateProvider) SentryDependencyContainer.sharedInstance().framesTracker.setDisplayLinkWrapper(displayLinkWrapper) SentryDependencyContainer.sharedInstance().framesTracker.start() @@ -1072,24 +1073,32 @@ class SentryTracerTests: XCTestCase { func testAddFramesMeasurement() { let sut = fixture.getSut() - let slowFrames = 4 + let displayLink = fixture.displayLinkWrapper + + let slowFrames = 1 let frozenFrames = 1 let normalFrames = 100 let totalFrames = slowFrames + frozenFrames + normalFrames - fixture.displayLinkWrapper.renderFrames(slowFrames, frozenFrames, normalFrames) + _ = displayLink.slowestSlowFrame() + _ = displayLink.fastestFrozenFrame() + displayLink.renderFrames(0, 0, normalFrames) sut.finish() - XCTAssertEqual(1, fixture.hub.capturedEventsWithScopes.count) + expect(self.fixture.hub.capturedEventsWithScopes.count) == 1 let serializedTransaction = fixture.hub.capturedEventsWithScopes.first!.event.serialize() - let measurements = serializedTransaction["measurements"] as? [String: [String: Int]] + let measurements = serializedTransaction["measurements"] as? [String: [String: Any]] + + expect(measurements?["frames_total"] as? [String: Int]) == ["value": totalFrames] + expect(measurements?["frames_slow"] as? [String: Int]) == ["value": slowFrames] + expect(measurements?["frames_frozen"] as? [String: Int]) == ["value": frozenFrames] + + let framesDelay = measurements?["frames_delay"] as? [String: NSNumber] + let expectedFrameDuration = slowFrameThreshold(displayLink.currentFrameRate.rawValue) + let expectedDelay = displayLink.slowestSlowFrameDuration + displayLink.fastestFrozenFrameDuration - expectedFrameDuration * 2 as NSNumber - XCTAssertEqual([ - "frames_total": ["value": totalFrames], - "frames_slow": ["value": slowFrames], - "frames_frozen": ["value": frozenFrames] - ], measurements) - XCTAssertNil(SentrySDK.getAppStartMeasurement()) + expect(framesDelay?["value"] as? NSNumber).to(beCloseTo(expectedDelay, within: 0.0001)) + expect(SentrySDK.getAppStartMeasurement()) == nil } func testNegativeFramesAmount_NoMeasurementAdded() { From 734159690eec9992816f7a923d333c83cb44152c Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 7 Dec 2023 10:39:19 +0100 Subject: [PATCH 21/33] changelog --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f40645a1527..72cb1233a1b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,7 +4,7 @@ ## Features -- Add slow and frozen frames to spans (#3450) +- Add frames delay to transactions (#3487) - Add slow and frozen frames to spans (#3450, #3478) ## 8.17.1 From 7610dcee045400f1b8dde1dc64f0a3bd959b3fa8 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 7 Dec 2023 10:43:56 +0100 Subject: [PATCH 22/33] test case for zero --- .../Transaction/SentryTracerTests.swift | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/Tests/SentryTests/Transaction/SentryTracerTests.swift b/Tests/SentryTests/Transaction/SentryTracerTests.swift index c1f5cae15b0..b5a9c1c0250 100644 --- a/Tests/SentryTests/Transaction/SentryTracerTests.swift +++ b/Tests/SentryTests/Transaction/SentryTracerTests.swift @@ -1101,6 +1101,23 @@ class SentryTracerTests: XCTestCase { expect(SentrySDK.getAppStartMeasurement()) == nil } + func testFramesDelay_WhenBeingZero() { + let sut = fixture.getSut() + + let displayLink = fixture.displayLinkWrapper + let normalFrames = 100 + displayLink.renderFrames(0, 0, normalFrames) + + sut.finish() + + expect(self.fixture.hub.capturedEventsWithScopes.count) == 1 + let serializedTransaction = fixture.hub.capturedEventsWithScopes.first!.event.serialize() + + let measurements = serializedTransaction["measurements"] as? [String: [String: Any]] + let framesDelay = measurements?["frames_delay"] as? [String: NSNumber] + expect(framesDelay?["value"] as? NSNumber).to(beCloseTo(0.0, within: 0.0001)) + } + func testNegativeFramesAmount_NoMeasurementAdded() { fixture.displayLinkWrapper.renderFrames(10, 10, 10) From 91429f0e616b4caacf3ace356480306d6072f592 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 7 Dec 2023 10:50:38 +0100 Subject: [PATCH 23/33] add frames delay for start up transactions --- Sources/Sentry/SentryTracer.m | 34 +++++++++++-------- .../Transaction/SentryTracerTests.swift | 14 ++++++-- 2 files changed, 30 insertions(+), 18 deletions(-) diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 95ff49d1b70..454d2cdde28 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -743,29 +743,33 @@ - (void)addMeasurements:(SentryTransaction *)transaction // Frames SentryFramesTracker *framesTracker = SentryDependencyContainer.sharedInstance.framesTracker; - if (framesTracker.isRunning && !_startTimeChanged) { - - SentryScreenFrames *currentFrames = framesTracker.currentFrames; - NSInteger totalFrames = currentFrames.total - initTotalFrames; - NSInteger slowFrames = currentFrames.slow - initSlowFrames; - NSInteger frozenFrames = currentFrames.frozen - initFrozenFrames; + if (framesTracker.isRunning) { CFTimeInterval framesDelay = [framesTracker getFramesDelay:self.startSystemTime endSystemTimestamp:SentryDependencyContainer.sharedInstance.dateProvider.systemTime]; + if (framesDelay >= 0) { [self setMeasurement:@"frames_delay" value:@(framesDelay)]; + SENTRY_LOG_DEBUG(@"Frames Delay:%f ms", framesDelay * 1000); } - if (sentryShouldAddSlowFrozenFramesData(totalFrames, slowFrames, frozenFrames)) { - [self setMeasurement:@"frames_total" value:@(totalFrames)]; - [self setMeasurement:@"frames_slow" value:@(slowFrames)]; - [self setMeasurement:@"frames_frozen" value:@(frozenFrames)]; - - SENTRY_LOG_DEBUG(@"Frames for transaction \"%@\" Total:%ld Slow:%ld " - @"Frozen:%ld Delay:%f ms", - self.operation, (long)totalFrames, (long)slowFrames, (long)frozenFrames, - framesDelay * 1000); + if (!_startTimeChanged) { + SentryScreenFrames *currentFrames = framesTracker.currentFrames; + NSInteger totalFrames = currentFrames.total - initTotalFrames; + NSInteger slowFrames = currentFrames.slow - initSlowFrames; + NSInteger frozenFrames = currentFrames.frozen - initFrozenFrames; + + if (sentryShouldAddSlowFrozenFramesData(totalFrames, slowFrames, frozenFrames)) { + [self setMeasurement:@"frames_total" value:@(totalFrames)]; + [self setMeasurement:@"frames_slow" value:@(slowFrames)]; + [self setMeasurement:@"frames_frozen" value:@(frozenFrames)]; + + SENTRY_LOG_DEBUG(@"Frames for transaction \"%@\" Total:%ld Slow:%ld " + @"Frozen:%ld Delay:%f ms", + self.operation, (long)totalFrames, (long)slowFrames, (long)frozenFrames, + framesDelay * 1000); + } } } } diff --git a/Tests/SentryTests/Transaction/SentryTracerTests.swift b/Tests/SentryTests/Transaction/SentryTracerTests.swift index b5a9c1c0250..d1bf4949f09 100644 --- a/Tests/SentryTests/Transaction/SentryTracerTests.swift +++ b/Tests/SentryTests/Transaction/SentryTracerTests.swift @@ -1060,14 +1060,22 @@ class SentryTracerTests: XCTestCase { #if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) - func testChangeStartTimeStamp_RemovesFramesMeasurement() throws { + func testChangeStartTimeStamp_OnlyFramesDelayAdded() throws { let sut = fixture.getSut() - fixture.displayLinkWrapper.renderFrames(1, 1, 1) + fixture.displayLinkWrapper.renderFrames(0, 0, 100) sut.updateStartTime(try XCTUnwrap(sut.startTimestamp).addingTimeInterval(-1)) sut.finish() - assertNoMeasurementsAdded() + expect(self.fixture.hub.capturedEventsWithScopes.count) == 1 + let serializedTransaction = fixture.hub.capturedEventsWithScopes.first!.event.serialize() + + let measurements = serializedTransaction["measurements"] as? [String: [String: Any]] + + expect(measurements?.count) == 1 + + let framesDelay = measurements?["frames_delay"] as? [String: NSNumber] + expect(framesDelay?["value"] as? NSNumber).to(beCloseTo(0.0, within: 0.0001)) } func testAddFramesMeasurement() { From 90a3a931deeb0ba10c0c7d388e63fb6365a721f1 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 7 Dec 2023 11:13:57 +0100 Subject: [PATCH 24/33] Fix build error --- Sources/Sentry/SentryTracer.m | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 454d2cdde28..51cbdd33c3f 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -61,6 +61,7 @@ @interface SentryTracer () +@property (nonatomic) uint64_t startSystemTime; @property (nonatomic) SentrySpanStatus finishStatus; /** This property is different from @c isFinished. While @c isFinished states if the tracer is * actually finished, this property tells you if finish was called on the tracer. Calling @@ -72,7 +73,6 @@ #if SENTRY_TARGET_PROFILING_SUPPORTED @property (nonatomic) BOOL isProfiling; -@property (nonatomic) uint64_t startSystemTime; #endif // SENTRY_TARGET_PROFILING_SUPPORTED @end @@ -130,6 +130,7 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti return nil; } + _startSystemTime = SentryDependencyContainer.sharedInstance.dateProvider.systemTime; _configuration = configuration; self.transactionContext = transactionContext; @@ -171,7 +172,6 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti #if SENTRY_TARGET_PROFILING_SUPPORTED if (_configuration.profilesSamplerDecision.decision == kSentrySampleDecisionYes) { - _startSystemTime = SentryDependencyContainer.sharedInstance.dateProvider.systemTime; _internalID = [[SentryId alloc] init]; _isProfiling = [SentryProfiler startWithTracer:_internalID]; } From db14da5d39b3197b63fe8383a01b297b9a519bf6 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 7 Dec 2023 13:55:40 +0100 Subject: [PATCH 25/33] undo swift sample change --- Samples/iOS-Swift/iOS-Swift/AppDelegate.swift | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Samples/iOS-Swift/iOS-Swift/AppDelegate.swift b/Samples/iOS-Swift/iOS-Swift/AppDelegate.swift index db75d3af174..cc03cd4b789 100644 --- a/Samples/iOS-Swift/iOS-Swift/AppDelegate.swift +++ b/Samples/iOS-Swift/iOS-Swift/AppDelegate.swift @@ -68,7 +68,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate { scope.setTag(value: "swift", key: "language") let user = User(userId: "1") - user.email = "philipp@example.com" + user.email = "tony@example.com" scope.setUser(user) if let path = Bundle.main.path(forResource: "Tongariro", ofType: "jpg") { From 47640529524eaf5515276b059879102819a5f7ee Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 7 Dec 2023 13:58:21 +0100 Subject: [PATCH 26/33] fix some warnings --- Tests/SentryTests/Transaction/SentryTracerTests.swift | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/Tests/SentryTests/Transaction/SentryTracerTests.swift b/Tests/SentryTests/Transaction/SentryTracerTests.swift index d1bf4949f09..bdac64cde72 100644 --- a/Tests/SentryTests/Transaction/SentryTracerTests.swift +++ b/Tests/SentryTests/Transaction/SentryTracerTests.swift @@ -1075,7 +1075,7 @@ class SentryTracerTests: XCTestCase { expect(measurements?.count) == 1 let framesDelay = measurements?["frames_delay"] as? [String: NSNumber] - expect(framesDelay?["value"] as? NSNumber).to(beCloseTo(0.0, within: 0.0001)) + expect(framesDelay?["value"]).to(beCloseTo(0.0, within: 0.0001)) } func testAddFramesMeasurement() { @@ -1105,7 +1105,7 @@ class SentryTracerTests: XCTestCase { let expectedFrameDuration = slowFrameThreshold(displayLink.currentFrameRate.rawValue) let expectedDelay = displayLink.slowestSlowFrameDuration + displayLink.fastestFrozenFrameDuration - expectedFrameDuration * 2 as NSNumber - expect(framesDelay?["value"] as? NSNumber).to(beCloseTo(expectedDelay, within: 0.0001)) + expect(framesDelay?["value"]).to(beCloseTo(expectedDelay, within: 0.0001)) expect(SentrySDK.getAppStartMeasurement()) == nil } @@ -1123,7 +1123,7 @@ class SentryTracerTests: XCTestCase { let measurements = serializedTransaction["measurements"] as? [String: [String: Any]] let framesDelay = measurements?["frames_delay"] as? [String: NSNumber] - expect(framesDelay?["value"] as? NSNumber).to(beCloseTo(0.0, within: 0.0001)) + expect(framesDelay?["value"]).to(beCloseTo(0.0, within: 0.0001)) } func testNegativeFramesAmount_NoMeasurementAdded() { From 74a75502f3590f0b03a1a76dc233fdde36b50543 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 7 Dec 2023 16:46:28 +0100 Subject: [PATCH 27/33] fix profiling tests --- Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift b/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift index a11007012ee..8aa8b5e7d3c 100644 --- a/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift +++ b/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift @@ -36,7 +36,7 @@ class SentryProfilerSwiftTests: XCTestCase { #if !os(macOS) lazy var displayLinkWrapper = TestDisplayLinkWrapper(dateProvider: currentDateProvider) - lazy var framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper) + lazy var framesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: currentDateProvider, keepDelayedFramesDuration: 0) #endif init() { From ef3e39de0568f7ec4639449870b2e65823b91733 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 14 Dec 2023 09:11:55 +0100 Subject: [PATCH 28/33] code comments --- Sources/Sentry/SentryFramesTracker.m | 4 +-- .../include/SentryDelayedFramesTracker.h | 32 +++++++++++++++++++ 2 files changed, 33 insertions(+), 3 deletions(-) diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index 1acab6c933a..06237d902af 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -138,9 +138,7 @@ - (void)displayLinkCallback // targetTimestamp is only available on iOS 10.0 and tvOS 10.0 and above. We use a fallback of // 60 fps. _currentFrameRate = 60; - if (UNLIKELY((self.displayLinkWrapper.targetTimestamp == self.displayLinkWrapper.timestamp))) { - _currentFrameRate = 60; - } else { + if (self.displayLinkWrapper.targetTimestamp != self.displayLinkWrapper.timestamp) { _currentFrameRate = (uint64_t)round( (1 / (self.displayLinkWrapper.targetTimestamp - self.displayLinkWrapper.timestamp))); } diff --git a/Sources/Sentry/include/SentryDelayedFramesTracker.h b/Sources/Sentry/include/SentryDelayedFramesTracker.h index f355f2a945d..7606e4bce23 100644 --- a/Sources/Sentry/include/SentryDelayedFramesTracker.h +++ b/Sources/Sentry/include/SentryDelayedFramesTracker.h @@ -10,6 +10,14 @@ NS_ASSUME_NONNULL_BEGIN @interface SentryDelayedFramesTracker : NSObject SENTRY_NO_INIT +/** + * Initializes a @c SentryDelayedFramesTracker. This class keeps track of information on delayed + * frames. Whenever a new delayed frame is recorded, it removes recorded delayed frames older than + * the current time minus the @c keepDelayedFramesDuration. + * + * @param keepDelayedFramesDuration The maximum duration to keep delayed frames records in memory. + * @param dateProvider The instance of a date provider. + */ - (instancetype)initWithKeepDelayedFramesDuration:(CFTimeInterval)keepDelayedFramesDuration dateProvider:(SentryCurrentDateProvider *)dateProvider; @@ -19,6 +27,30 @@ SENTRY_NO_INIT expectedDuration:(CFTimeInterval)expectedDuration actualDuration:(CFTimeInterval)actualDuration; +/** + * This method returns the duration of all delayed frames between startSystemTimestamp and + * endSystemTimestamp. + * + * @discussion The frames delay for one recorded delayed frame is the intersection of the delayed + * part with the queried time interval of startSystemTimestamp and endSystemTimestamp. For example, + * the expected frame duration is 16.67 ms, and the frame took 20 ms to render. The frame delay is + * 20 ms - 16.67 ms = 3.33 ms. Parts of the delay may occur before the queried time interval. For + * example, of the 3.33 ms of a recorded frames delay only 2 ms intersect with the queried time + * interval. In that case, the frames delay is only 2 ms. This method also considers when there is + * no recorded frame information for the queried time interval, but there should be, meaning it + * includes ongoing, not yet recorded frames as frames delay. + * + * + * @param startSystemTimestamp The start system time stamp for the time interval to query frames + * 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 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 From 52e86b92514fc334f603a72fc05452a6dc66c8d2 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 14 Dec 2023 09:37:34 +0100 Subject: [PATCH 29/33] send as span data instead of measurement --- Sources/Sentry/SentryTracer.m | 26 ++++++++++--------- .../Transaction/SentryTracerTests.swift | 22 ++++++++-------- 2 files changed, 25 insertions(+), 23 deletions(-) diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 51cbdd33c3f..e3c4ec74502 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -607,6 +607,18 @@ - (void)updateStartTime:(NSDate *)startTime - (SentryTransaction *)toTransaction { + SentryFramesTracker *framesTracker = SentryDependencyContainer.sharedInstance.framesTracker; + if (framesTracker.isRunning) { + CFTimeInterval framesDelay = [framesTracker + getFramesDelay:self.startSystemTime + endSystemTimestamp:SentryDependencyContainer.sharedInstance.dateProvider.systemTime]; + + if (framesDelay >= 0) { + [self setDataValue:@(framesDelay) forKey:@"frames.delay"]; + SENTRY_LOG_DEBUG(@"Frames Delay:%f ms", framesDelay * 1000); + } + } + NSUInteger capacity; #if SENTRY_HAS_UIKIT NSArray> *appStartSpans = sentryBuildAppStartSpans(self, appStartMeasurement); @@ -745,15 +757,6 @@ - (void)addMeasurements:(SentryTransaction *)transaction SentryFramesTracker *framesTracker = SentryDependencyContainer.sharedInstance.framesTracker; if (framesTracker.isRunning) { - CFTimeInterval framesDelay = [framesTracker - getFramesDelay:self.startSystemTime - endSystemTimestamp:SentryDependencyContainer.sharedInstance.dateProvider.systemTime]; - - if (framesDelay >= 0) { - [self setMeasurement:@"frames_delay" value:@(framesDelay)]; - SENTRY_LOG_DEBUG(@"Frames Delay:%f ms", framesDelay * 1000); - } - if (!_startTimeChanged) { SentryScreenFrames *currentFrames = framesTracker.currentFrames; NSInteger totalFrames = currentFrames.total - initTotalFrames; @@ -766,9 +769,8 @@ - (void)addMeasurements:(SentryTransaction *)transaction [self setMeasurement:@"frames_frozen" value:@(frozenFrames)]; SENTRY_LOG_DEBUG(@"Frames for transaction \"%@\" Total:%ld Slow:%ld " - @"Frozen:%ld Delay:%f ms", - self.operation, (long)totalFrames, (long)slowFrames, (long)frozenFrames, - framesDelay * 1000); + @"Frozen:%ld", + self.operation, (long)totalFrames, (long)slowFrames, (long)frozenFrames); } } } diff --git a/Tests/SentryTests/Transaction/SentryTracerTests.swift b/Tests/SentryTests/Transaction/SentryTracerTests.swift index bdac64cde72..122d04d3bf4 100644 --- a/Tests/SentryTests/Transaction/SentryTracerTests.swift +++ b/Tests/SentryTests/Transaction/SentryTracerTests.swift @@ -1070,12 +1070,10 @@ class SentryTracerTests: XCTestCase { expect(self.fixture.hub.capturedEventsWithScopes.count) == 1 let serializedTransaction = fixture.hub.capturedEventsWithScopes.first!.event.serialize() - let measurements = serializedTransaction["measurements"] as? [String: [String: Any]] - - expect(measurements?.count) == 1 + let extra = serializedTransaction["extra"] as? [String: Any] - let framesDelay = measurements?["frames_delay"] as? [String: NSNumber] - expect(framesDelay?["value"]).to(beCloseTo(0.0, within: 0.0001)) + let framesDelay = extra?["frames.delay"] as? NSNumber + expect(framesDelay).to(beCloseTo(0.0, within: 0.0001)) } func testAddFramesMeasurement() { @@ -1101,11 +1099,13 @@ class SentryTracerTests: XCTestCase { expect(measurements?["frames_slow"] as? [String: Int]) == ["value": slowFrames] expect(measurements?["frames_frozen"] as? [String: Int]) == ["value": frozenFrames] - let framesDelay = measurements?["frames_delay"] as? [String: NSNumber] + let extra = serializedTransaction["extra"] as? [String: Any] + let framesDelay = extra?["frames.delay"] as? NSNumber + let expectedFrameDuration = slowFrameThreshold(displayLink.currentFrameRate.rawValue) let expectedDelay = displayLink.slowestSlowFrameDuration + displayLink.fastestFrozenFrameDuration - expectedFrameDuration * 2 as NSNumber - expect(framesDelay?["value"]).to(beCloseTo(expectedDelay, within: 0.0001)) + expect(framesDelay).to(beCloseTo(expectedDelay, within: 0.0001)) expect(SentrySDK.getAppStartMeasurement()) == nil } @@ -1119,11 +1119,11 @@ class SentryTracerTests: XCTestCase { sut.finish() expect(self.fixture.hub.capturedEventsWithScopes.count) == 1 - let serializedTransaction = fixture.hub.capturedEventsWithScopes.first!.event.serialize() - let measurements = serializedTransaction["measurements"] as? [String: [String: Any]] - let framesDelay = measurements?["frames_delay"] as? [String: NSNumber] - expect(framesDelay?["value"]).to(beCloseTo(0.0, within: 0.0001)) + let serializedTransaction = fixture.hub.capturedEventsWithScopes.first!.event.serialize() + let extra = serializedTransaction["extra"] as? [String: Any] + let framesDelay = extra?["frames.delay"] as? NSNumber + expect(framesDelay).to(beCloseTo(0.0, within: 0.0001)) } func testNegativeFramesAmount_NoMeasurementAdded() { From 8cb98ad8940a871cef841588d3fd8f249fca6516 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 14 Dec 2023 09:43:08 +0100 Subject: [PATCH 30/33] refactor --- Sources/Sentry/SentryTracer.m | 26 +++++++++++++------------- 1 file changed, 13 insertions(+), 13 deletions(-) diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index e3c4ec74502..6dbd767a8f3 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -607,17 +607,7 @@ - (void)updateStartTime:(NSDate *)startTime - (SentryTransaction *)toTransaction { - SentryFramesTracker *framesTracker = SentryDependencyContainer.sharedInstance.framesTracker; - if (framesTracker.isRunning) { - CFTimeInterval framesDelay = [framesTracker - getFramesDelay:self.startSystemTime - endSystemTimestamp:SentryDependencyContainer.sharedInstance.dateProvider.systemTime]; - - if (framesDelay >= 0) { - [self setDataValue:@(framesDelay) forKey:@"frames.delay"]; - SENTRY_LOG_DEBUG(@"Frames Delay:%f ms", framesDelay * 1000); - } - } + [self setFramesStatistics]; NSUInteger capacity; #if SENTRY_HAS_UIKIT @@ -752,11 +742,21 @@ - (void)addMeasurements:(SentryTransaction *)transaction [transaction setContext:context]; } } +} - // Frames +- (void)setFramesStatistics +{ SentryFramesTracker *framesTracker = SentryDependencyContainer.sharedInstance.framesTracker; - if (framesTracker.isRunning) { + CFTimeInterval framesDelay = [framesTracker + getFramesDelay:self.startSystemTime + endSystemTimestamp:SentryDependencyContainer.sharedInstance.dateProvider.systemTime]; + + if (framesDelay >= 0) { + [self setDataValue:@(framesDelay) forKey:@"frames.delay"]; + SENTRY_LOG_DEBUG(@"Frames Delay:%f ms", framesDelay * 1000); + } + if (!_startTimeChanged) { SentryScreenFrames *currentFrames = framesTracker.currentFrames; NSInteger totalFrames = currentFrames.total - initTotalFrames; From 6bdba420d9df651e9fa949b9e8df19256b603b61 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 14 Dec 2023 09:44:55 +0100 Subject: [PATCH 31/33] more statistics --- Sources/Sentry/SentryTracer.m | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 6dbd767a8f3..78031ac82b8 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -607,10 +607,11 @@ - (void)updateStartTime:(NSDate *)startTime - (SentryTransaction *)toTransaction { - [self setFramesStatistics]; NSUInteger capacity; #if SENTRY_HAS_UIKIT + [self addFrameStatistics]; + NSArray> *appStartSpans = sentryBuildAppStartSpans(self, appStartMeasurement); capacity = _children.count + appStartSpans.count; #else @@ -656,7 +657,7 @@ - (SentryTransaction *)toTransaction } #if SENTRY_HAS_UIKIT - [self addMeasurements:transaction]; + [self addAppStartMeasurements:transaction]; if ([viewNames count] > 0) { transaction.viewNames = viewNames; @@ -716,7 +717,7 @@ - (nullable SentryAppStartMeasurement *)getAppStartMeasurement return measurement; } -- (void)addMeasurements:(SentryTransaction *)transaction +- (void)addAppStartMeasurements:(SentryTransaction *)transaction { if (appStartMeasurement != nil && appStartMeasurement.type != SentryAppStartTypeUnknown) { NSString *type = nil; @@ -744,7 +745,7 @@ - (void)addMeasurements:(SentryTransaction *)transaction } } -- (void)setFramesStatistics +- (void)addFrameStatistics { SentryFramesTracker *framesTracker = SentryDependencyContainer.sharedInstance.framesTracker; if (framesTracker.isRunning) { From 1af26ab94123f6d285277dc931f6b4c76db8601b Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 14 Dec 2023 10:55:15 +0100 Subject: [PATCH 32/33] refactoring --- Sources/Sentry/SentryDelayedFramesTracker.m | 26 ++++++++++----------- 1 file changed, 13 insertions(+), 13 deletions(-) diff --git a/Sources/Sentry/SentryDelayedFramesTracker.m b/Sources/Sentry/SentryDelayedFramesTracker.m index e18d9eac1f0..9486937b45a 100644 --- a/Sources/Sentry/SentryDelayedFramesTracker.m +++ b/Sources/Sentry/SentryDelayedFramesTracker.m @@ -142,6 +142,19 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp CFTimeInterval delay = ongoingDelayedFrame; + // We need to calculate the intersections of the queried TimestampInterval + // (startSystemTimestamp - endSystemTimestamp) with the recorded frame delays. Doing that + // with NSDateInterval makes things easier. Therefore, we convert the system timestamps to + // NSDate objects, although they don't represent the correct dates. We only need to know how + // long the intersections are to calculate the frame delay and not precisely when. + + NSDate *startDate = [NSDate + dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval(startSystemTimestamp)]; + NSDate *endDate = [NSDate + dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval(endSystemTimestamp)]; + NSDateInterval *queryDateInterval = [[NSDateInterval alloc] initWithStartDate:startDate + endDate:endDate]; + // Iterate in reverse order, as younger frame delays are more likely to match the queried // period. for (SentryDelayedFrame *frame in frames.reverseObjectEnumerator) { @@ -152,19 +165,6 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp break; } - // We need to calculate the intersections of the queried TimestampInterval - // (startSystemTimestamp - endSystemTimestamp) with the recorded frame delays. Doing that - // with NSDateInterval makes things easier. Therefore, we convert the system timestamps to - // NSDate objects, although they don't represent the correct dates. We only need to know how - // long the intersections are to calculate the frame delay and not precisely when. - - NSDate *startDate = [NSDate - dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval(startSystemTimestamp)]; - NSDate *endDate = [NSDate - dateWithTimeIntervalSinceReferenceDate:nanosecondsToTimeInterval(endSystemTimestamp)]; - NSDateInterval *queryDateInterval = [[NSDateInterval alloc] initWithStartDate:startDate - endDate:endDate]; - CFTimeInterval delayStartTime = nanosecondsToTimeInterval(frame.startSystemTimestamp) + frame.expectedDuration; NSDate *frameDelayStartDate = From 3af37dae63e34f1c65e0bbe161db39a3a48f5b94 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 14 Dec 2023 11:16:18 +0100 Subject: [PATCH 33/33] fix an edge case --- Sources/Sentry/SentryDelayedFramesTracker.m | 5 ++ .../SentryFramesTrackerTests.swift | 57 +++++++++++++++++++ 2 files changed, 62 insertions(+) diff --git a/Sources/Sentry/SentryDelayedFramesTracker.m b/Sources/Sentry/SentryDelayedFramesTracker.m index 9486937b45a..0ef44cb59e8 100644 --- a/Sources/Sentry/SentryDelayedFramesTracker.m +++ b/Sources/Sentry/SentryDelayedFramesTracker.m @@ -115,6 +115,11 @@ - (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp return cantCalculateFrameDelayReturnValue; } + if (previousFrameTimestamp < 0) { + SENTRY_LOG_DEBUG(@"Not calculating frames delay because no frames yet recorded."); + return cantCalculateFrameDelayReturnValue; + } + NSArray *frames; @synchronized(self.delayedFrames) { uint64_t oldestDelayedFrameStartTimestamp = UINT64_MAX; diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index 47c0ecd0460..042a33e2ed0 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -264,6 +264,63 @@ class SentryFramesTrackerTests: XCTestCase { testFrameDelay(timeIntervalAfterFrameStart: timeIntervalAfterFrameStart, timeIntervalBeforeFrameEnd: timeIntervalBeforeFrameEnd, expectedDelay: expectedDelay) } + func testDelayedFrames_NoRecordedFrames_MinusOne() { + fixture.dateProvider.advance(by: 2.0) + + let sut = fixture.sut + sut.start() + + let startSystemTime = fixture.dateProvider.systemTime() + + fixture.dateProvider.advance(by: 0.001) + + let endSystemTime = fixture.dateProvider.systemTime() + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay) == -1 + } + + func testDelayedFrames_NoRecordedDelayedFrames_ReturnsZero() { + fixture.dateProvider.advance(by: 2.0) + + let sut = fixture.sut + sut.start() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + + let startSystemTime = fixture.dateProvider.systemTime() + + fixture.dateProvider.advance(by: 0.001) + + let endSystemTime = fixture.dateProvider.systemTime() + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay).to(beCloseTo(0.0, within: 0.0001)) + } + + func testDelayedFrames_NoRecordedDelayedFrames_ButFrameIsDelayed_ReturnsDelay() { + fixture.dateProvider.advance(by: 2.0) + + let sut = fixture.sut + sut.start() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + + let startSystemTime = fixture.dateProvider.systemTime() + + let delay = 0.5 + fixture.dateProvider.advance(by: delay) + + let endSystemTime = fixture.dateProvider.systemTime() + + let expectedDelay = delay - slowFrameThreshold(fixture.displayLinkWrapper.currentFrameRate.rawValue) + + 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()