From de033daa1cfa7690b0644ba9292b69259d386266 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 14 Dec 2023 14:08:59 +0100 Subject: [PATCH] feat: Add frames delay to transactions (#3487) Add frames delay as span data to transactions. --- CHANGELOG.md | 1 + Sentry.xcodeproj/project.pbxproj | 16 + SentryTestUtils/TestDisplayLinkWrapper.swift | 8 +- Sources/Sentry/SentryDelayedFrame.m | 25 ++ Sources/Sentry/SentryDelayedFramesTracker.m | 196 +++++++++ Sources/Sentry/SentryDependencyContainer.m | 5 +- Sources/Sentry/SentryFramesTracker.m | 54 ++- Sources/Sentry/SentryTracer.m | 49 ++- Sources/Sentry/include/SentryDelayedFrame.h | 22 + .../include/SentryDelayedFramesTracker.h | 65 +++ Sources/Sentry/include/SentryFramesTracker.h | 12 +- Sources/Sentry/include/SentryTracer.h | 2 + .../SentryProfilerSwiftTests.swift | 2 +- .../SentryFramesTrackerTests.swift | 385 +++++++++++++++++- .../SentryTimeToDisplayTrackerTest.swift | 2 +- .../Transaction/SentrySpanTests.swift | 2 +- .../Transaction/SentryTracerTests.swift | 62 ++- 17 files changed, 847 insertions(+), 61 deletions(-) create mode 100644 Sources/Sentry/SentryDelayedFrame.m create mode 100644 Sources/Sentry/SentryDelayedFramesTracker.m create mode 100644 Sources/Sentry/include/SentryDelayedFrame.h create mode 100644 Sources/Sentry/include/SentryDelayedFramesTracker.h diff --git a/CHANGELOG.md b/CHANGELOG.md index 5398bf41268..72cb1233a1b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ ## Features +- Add frames delay to transactions (#3487) - Add slow and frozen frames to spans (#3450, #3478) ## 8.17.1 diff --git a/Sentry.xcodeproj/project.pbxproj b/Sentry.xcodeproj/project.pbxproj index 3aba2bee9f8..e36918fc974 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 */; }; @@ -91,6 +93,8 @@ 62B86CFC29F052BB008F3947 /* SentryTestLogConfig.m in Sources */ = {isa = PBXBuildFile; fileRef = 62B86CFB29F052BB008F3947 /* SentryTestLogConfig.m */; }; 62C25C862B075F4900C68CBD /* TestOptions.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62C25C852B075F4900C68CBD /* TestOptions.swift */; }; 62C3168B2B1F865A000D7031 /* SentryTimeSwiftTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 62C3168A2B1F865A000D7031 /* SentryTimeSwiftTests.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 */; }; @@ -995,6 +999,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 = ""; }; @@ -1004,6 +1010,8 @@ 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 = ""; }; 62C3168A2B1F865A000D7031 /* SentryTimeSwiftTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryTimeSwiftTests.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 = ""; }; @@ -2943,6 +2951,10 @@ 7B6C5EDD264E8DF00010D138 /* SentryFramesTracker.m */, 7B7A599426B692540060A676 /* SentryScreenFrames.h */, 7B7A599626B692F00060A676 /* SentryScreenFrames.m */, + 62862B1B2B1DDBC8009B16E3 /* SentryDelayedFrame.h */, + 62862B1D2B1DDC35009B16E3 /* SentryDelayedFrame.m */, + 62C316802B1F2E93000D7031 /* SentryDelayedFramesTracker.h */, + 62C316822B1F2EA1000D7031 /* SentryDelayedFramesTracker.m */, ); name = FramesTracking; sourceTree = ""; @@ -3573,6 +3585,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 */, @@ -3628,6 +3641,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 */, @@ -4136,6 +4150,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 */, @@ -4229,6 +4244,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/SentryTestUtils/TestDisplayLinkWrapper.swift b/SentryTestUtils/TestDisplayLinkWrapper.swift index 4110f52e1a5..5f1016990e0 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 @@ -25,10 +23,12 @@ 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. + public let timeEpsilon = 0.001 public init(dateProvider: TestCurrentDateProvider = TestCurrentDateProvider()) { self.dateProvider = dateProvider 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/SentryDelayedFramesTracker.m b/Sources/Sentry/SentryDelayedFramesTracker.m new file mode 100644 index 00000000000..0ef44cb59e8 --- /dev/null +++ b/Sources/Sentry/SentryDelayedFramesTracker.m @@ -0,0 +1,196 @@ +#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]; + + 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; + } + + NSUInteger left = 0; + NSUInteger right = self.delayedFrames.count; + + while (left < right) { + NSUInteger mid = (left + right) / 2; + SentryDelayedFrame *midFrame = self.delayedFrames[mid]; + + uint64_t frameEndSystemTimeStamp + = midFrame.startSystemTimestamp + timeIntervalToNanoseconds(midFrame.actualDuration); + if (frameEndSystemTimeStamp >= removeFramesBeforeSystemTimeStamp) { + right = mid; + } else { + left = mid + 1; + } + } + + [self.delayedFrames removeObjectsInRange:NSMakeRange(0, left)]; +} + +- (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; + } + + 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; + 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; + + // 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) { + + uint64_t frameEndSystemTimeStamp + = frame.startSystemTimestamp + timeIntervalToNanoseconds(frame.actualDuration); + if (frameEndSystemTimeStamp < startSystemTimestamp) { + break; + } + + CFTimeInterval delayStartTime + = nanosecondsToTimeInterval(frame.startSystemTimestamp) + frame.expectedDuration; + NSDate *frameDelayStartDate = + [NSDate dateWithTimeIntervalSinceReferenceDate:delayStartTime]; + + NSDateInterval *frameDelayDateInterval = [[NSDateInterval alloc] + initWithStartDate:frameDelayStartDate + duration:(frame.actualDuration - frame.expectedDuration)]; + + if ([queryDateInterval intersectsDateInterval:frameDelayDateInterval]) { + NSDateInterval *intersection = + [queryDateInterval intersectionWithDateInterval:frameDelayDateInterval]; + delay = delay + intersection.duration; + } + } + + return delay; +} + +@end + +NS_ASSUME_NONNULL_END + +#endif // SENTRY_HAS_UIKIT diff --git a/Sources/Sentry/SentryDependencyContainer.m b/Sources/Sentry/SentryDependencyContainer.m index dd04aaa1ff6..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" @@ -268,7 +269,9 @@ - (SentryFramesTracker *)framesTracker @synchronized(sentryDependencyContainerLock) { if (_framesTracker == nil) { _framesTracker = [[SentryFramesTracker alloc] - initWithDisplayLinkWrapper:[[SentryDisplayLinkWrapper alloc] init]]; + initWithDisplayLinkWrapper:[[SentryDisplayLinkWrapper alloc] init] + dateProvider:self.dateProvider + keepDelayedFramesDuration:SENTRY_AUTO_TRANSACTION_MAX_DURATION]; } } } diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m index 76da05f6b35..06237d902af 100644 --- a/Sources/Sentry/SentryFramesTracker.m +++ b/Sources/Sentry/SentryFramesTracker.m @@ -4,7 +4,8 @@ # import "SentryCompiler.h" # import "SentryCurrentDateProvider.h" -# import "SentryDependencyContainer.h" +# import "SentryDelayedFrame.h" +# import "SentryDelayedFramesTracker.h" # import "SentryDisplayLinkWrapper.h" # import "SentryLog.h" # import "SentryProfiler.h" @@ -26,8 +27,10 @@ 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) uint64_t currentFrameRate; @property (nonatomic, strong) NSHashTable> *listeners; # if SENTRY_TARGET_PROFILING_SUPPORTED @property (nonatomic, readwrite) SentryMutableFrameInfoTimeSeries *frozenFrameTimestamps; @@ -35,6 +38,8 @@ @property (nonatomic, readwrite) SentryMutableFrameInfoTimeSeries *frameRateTimestamps; # endif // SENTRY_TARGET_PROFILING_SUPPORTED +@property (nonatomic, strong) SentryDelayedFramesTracker *delayedFramesTracker; + @end CFTimeInterval @@ -52,11 +57,20 @@ @implementation SentryFramesTracker { } - (instancetype)initWithDisplayLinkWrapper:(SentryDisplayLinkWrapper *)displayLinkWrapper + dateProvider:(SentryCurrentDateProvider *)dateProvider + keepDelayedFramesDuration:(CFTimeInterval)keepDelayedFramesDuration { if (self = [super init]) { _isRunning = NO; _displayLinkWrapper = displayLinkWrapper; + _dateProvider = dateProvider; + _delayedFramesTracker = [[SentryDelayedFramesTracker alloc] + initWithKeepDelayedFramesDuration:keepDelayedFramesDuration + dateProvider:dateProvider]; + _listeners = [NSHashTable weakObjectsHashTable]; + + _currentFrameRate = 60; [self resetFrames]; SENTRY_LOG_DEBUG(@"Initialized frame tracker %@", self); } @@ -80,6 +94,8 @@ - (void)resetFrames # if SENTRY_TARGET_PROFILING_SUPPORTED [self resetProfilingTimestamps]; # endif // SENTRY_TARGET_PROFILING_SUPPORTED + + [self.delayedFramesTracker resetDelayedFramesTimeStamps]; } # if SENTRY_TARGET_PROFILING_SUPPORTED @@ -105,8 +121,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; @@ -122,11 +137,9 @@ - (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; - if (UNLIKELY((self.displayLinkWrapper.targetTimestamp == self.displayLinkWrapper.timestamp))) { - currentFrameRate = 60; - } else { - currentFrameRate = (uint64_t)round( + _currentFrameRate = 60; + if (self.displayLinkWrapper.targetTimestamp != self.displayLinkWrapper.timestamp) { + _currentFrameRate = (uint64_t)round( (1 / (self.displayLinkWrapper.targetTimestamp - self.displayLinkWrapper.timestamp))); } @@ -135,12 +148,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]; } } @@ -148,7 +161,7 @@ - (void)displayLinkCallback CFTimeInterval frameDuration = thisFrameTimestamp - self.previousFrameTimestamp; - if (frameDuration > slowFrameThreshold(currentFrameRate) + if (frameDuration > slowFrameThreshold(_currentFrameRate) && frameDuration <= SentryFrozenFrameThreshold) { _slowFrames++; # if SENTRY_TARGET_PROFILING_SUPPORTED @@ -167,6 +180,13 @@ - (void)displayLinkCallback array:self.frozenFrameTimestamps]; # endif // SENTRY_TARGET_PROFILING_SUPPORTED } + + if (frameDuration > slowFrameThreshold(_currentFrameRate)) { + [self.delayedFramesTracker recordDelayedFrame:self.previousFrameSystemTimestamp + expectedDuration:slowFrameThreshold(_currentFrameRate) + actualDuration:frameDuration]; + } + _totalFrames++; self.previousFrameTimestamp = thisFrameTimestamp; self.previousFrameSystemTimestamp = thisFrameSystemTimestamp; @@ -214,6 +234,17 @@ - (SentryScreenFrames *)currentFrames # endif // SENTRY_TARGET_PROFILING_SUPPORTED } +- (CFTimeInterval)getFramesDelay:(uint64_t)startSystemTimestamp + endSystemTimestamp:(uint64_t)endSystemTimestamp +{ + return [self.delayedFramesTracker getFramesDelay:startSystemTimestamp + endSystemTimestamp:endSystemTimestamp + isRunning:_isRunning + thisFrameTimestamp:self.displayLinkWrapper.timestamp + previousFrameTimestamp:self.previousFrameTimestamp + slowFrameThreshold:slowFrameThreshold(_currentFrameRate)]; +} + - (void)addListener:(id)listener { @@ -233,6 +264,7 @@ - (void)stop { _isRunning = NO; [self.displayLinkWrapper invalidate]; + [self.delayedFramesTracker resetDelayedFramesTimeStamps]; } - (void)dealloc diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m index 39284809123..78031ac82b8 100644 --- a/Sources/Sentry/SentryTracer.m +++ b/Sources/Sentry/SentryTracer.m @@ -56,12 +56,12 @@ 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 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 @@ -73,7 +73,6 @@ #if SENTRY_TARGET_PROFILING_SUPPORTED @property (nonatomic) BOOL isProfiling; -@property (nonatomic) uint64_t startSystemTime; #endif // SENTRY_TARGET_PROFILING_SUPPORTED @end @@ -131,6 +130,7 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti return nil; } + _startSystemTime = SentryDependencyContainer.sharedInstance.dateProvider.systemTime; _configuration = configuration; self.transactionContext = transactionContext; @@ -172,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]; } @@ -608,8 +607,11 @@ - (void)updateStartTime:(NSDate *)startTime - (SentryTransaction *)toTransaction { + NSUInteger capacity; #if SENTRY_HAS_UIKIT + [self addFrameStatistics]; + NSArray> *appStartSpans = sentryBuildAppStartSpans(self, appStartMeasurement); capacity = _children.count + appStartSpans.count; #else @@ -655,7 +657,7 @@ - (SentryTransaction *)toTransaction } #if SENTRY_HAS_UIKIT - [self addMeasurements:transaction]; + [self addAppStartMeasurements:transaction]; if ([viewNames count] > 0) { transaction.viewNames = viewNames; @@ -715,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; @@ -741,23 +743,36 @@ - (void)addMeasurements:(SentryTransaction *)transaction [transaction setContext:context]; } } +} - // Frames +- (void)addFrameStatistics +{ SentryFramesTracker *framesTracker = SentryDependencyContainer.sharedInstance.framesTracker; - if (framesTracker.isRunning && !_startTimeChanged) { + if (framesTracker.isRunning) { + CFTimeInterval framesDelay = [framesTracker + getFramesDelay:self.startSystemTime + endSystemTimestamp:SentryDependencyContainer.sharedInstance.dateProvider.systemTime]; - SentryScreenFrames *currentFrames = framesTracker.currentFrames; - NSInteger totalFrames = currentFrames.total - initTotalFrames; - NSInteger slowFrames = currentFrames.slow - initSlowFrames; - NSInteger frozenFrames = currentFrames.frozen - initFrozenFrames; + if (framesDelay >= 0) { + [self setDataValue:@(framesDelay) forKey:@"frames.delay"]; + 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)]; + if (!_startTimeChanged) { + SentryScreenFrames *currentFrames = framesTracker.currentFrames; + NSInteger totalFrames = currentFrames.total - initTotalFrames; + NSInteger slowFrames = currentFrames.slow - initSlowFrames; + NSInteger frozenFrames = currentFrames.frozen - initFrozenFrames; - SENTRY_LOG_DEBUG(@"Frames for transaction \"%@\" Total:%ld Slow:%ld Frozen:%ld", - self.operation, (long)totalFrames, (long)slowFrames, (long)frozenFrames); + 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); + } } } } 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 diff --git a/Sources/Sentry/include/SentryDelayedFramesTracker.h b/Sources/Sentry/include/SentryDelayedFramesTracker.h new file mode 100644 index 00000000000..7606e4bce23 --- /dev/null +++ b/Sources/Sentry/include/SentryDelayedFramesTracker.h @@ -0,0 +1,65 @@ +#import "SentryDefines.h" + +#if SENTRY_HAS_UIKIT + +@class SentryDisplayLinkWrapper; +@class SentryCurrentDateProvider; + +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; + +- (void)resetDelayedFramesTimeStamps; + +- (void)recordDelayedFrame:(uint64_t)startSystemTimestamp + 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 + thisFrameTimestamp:(CFTimeInterval)thisFrameTimestamp + previousFrameTimestamp:(CFTimeInterval)previousFrameTimestamp + slowFrameThreshold:(CFTimeInterval)slowFrameThreshold; + +@end + +NS_ASSUME_NONNULL_END + +#endif // SENTRY_HAS_UIKIT diff --git a/Sources/Sentry/include/SentryFramesTracker.h b/Sources/Sentry/include/SentryFramesTracker.h index 22e5c86e3b5..1e13b2ae63f 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,9 @@ NS_ASSUME_NONNULL_BEGIN */ @interface SentryFramesTracker : NSObject -- (instancetype)initWithDisplayLinkWrapper:(SentryDisplayLinkWrapper *)displayLinkWrapper; +- (instancetype)initWithDisplayLinkWrapper:(SentryDisplayLinkWrapper *)displayLinkWrapper + dateProvider:(SentryCurrentDateProvider *)dateProvider + keepDelayedFramesDuration:(CFTimeInterval)keepDelayedFramesDuration; @property (nonatomic, assign, readonly) SentryScreenFrames *currentFrames; @property (nonatomic, assign, readonly) BOOL isRunning; @@ -34,6 +37,13 @@ NS_ASSUME_NONNULL_BEGIN - (void)start; - (void)stop; +/* + * 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; - (void)removeListener:(id)listener; 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/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() { diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift index 6e8d6824fb6..042a33e2ed0 100644 --- a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift @@ -9,15 +9,21 @@ 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() + 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) + lazy var sut: SentryFramesTracker = SentryFramesTracker(displayLinkWrapper: displayLinkWrapper, dateProvider: dateProvider, keepDelayedFramesDuration: keepDelayedFramesDuration) } private var fixture: Fixture! @@ -76,12 +82,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) } @@ -149,6 +156,342 @@ 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 startSystemTime = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + displayLink.normalFrame() + _ = displayLink.fastestSlowFrame() + displayLink.normalFrame() + _ = displayLink.slowestSlowFrame() + + let endSystemTime = fixture.dateProvider.systemTime() + + let expectedDelay = displayLink.timeEpsilon + displayLink.slowestSlowFrameDuration - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + 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 startSystemTime = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + displayLink.normalFrame() + + let delayWithoutFrameRecord = 1.0 + fixture.dateProvider.advance(by: delayWithoutFrameRecord) + let endSystemTime = fixture.dateProvider.systemTime() + + let expectedDelay = delayWithoutFrameRecord - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + 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.slowestSlowFrameDuration - 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.slowestSlowFrameDuration - 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.slowestSlowFrameDuration - timeIntervalAfterFrameStart - timeIntervalBeforeFrameEnd + + 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() + + let slowFrameStartSystemTime = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + let endSystemTime = fixture.dateProvider.systemTime() - timeIntervalToNanoseconds(timeIntervalBeforeFrameEnd) + + let startSystemTime = slowFrameStartSystemTime + timeIntervalToNanoseconds(timeIntervalAfterFrameStart) + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + 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. + * + * [| e | delayed frame ] [| e | delayed frame - ] e = the expected frame duration + * [------ time interval ----- ] + */ + func testOneDelayedFrameStartsShortlyEndsBeforeTimeInterval() { + let sut = fixture.sut + sut.start() + + let startSystemTime = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + displayLink.normalFrame() + _ = displayLink.fastestSlowFrame() + + let timeIntervalBeforeFrameEnd = slowFrameThreshold(displayLink.currentFrameRate.rawValue) - 0.005 + let endSystemTime = fixture.dateProvider.systemTime() - timeIntervalToNanoseconds(timeIntervalBeforeFrameEnd) + + let expectedDelay = displayLink.slowestSlowFrameDuration - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + + func testFrameDelay_WithStartBeforeEnd_ReturnsMinusOne() { + let sut = fixture.sut + sut.start() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + let actualFrameDelay = sut.getFramesDelay(1, endSystemTimestamp: 0) + expect(actualFrameDelay) == -1.0 + } + + func testFrameDelay_LongestTimeStamp_ReturnsMinusOne() { + let sut = fixture.sut + sut.start() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + let actualFrameDelay = sut.getFramesDelay(0, endSystemTimestamp: UInt64.max) + expect(actualFrameDelay) == -1.0 + } + + func testFrameDelay_KeepAddingSlowFrames_OnlyTheMaxDurationFramesReturned() { + let sut = fixture.sut + sut.start() + + let (startSystemTime, _, expectedDelay) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) + + let endSystemTime = fixture.dateProvider.systemTime() + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + + func testFrameDelay_MoreThanMaxDuration_FrameInformationMissing_DelayReturned() { + let sut = fixture.sut + let displayLink = fixture.displayLinkWrapper + sut.start() + + let (startSystemTime, _, slowFramesDelay) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) + + let delayWithoutFrameRecord = 2.0 + fixture.dateProvider.advance(by: delayWithoutFrameRecord) + let endSystemTime = fixture.dateProvider.systemTime() + + let delayNotRecorded = delayWithoutFrameRecord - slowFrameThreshold(displayLink.currentFrameRate.rawValue) + let expectedDelay = slowFramesDelay + delayNotRecorded + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + } + + func testFrameDelay_MoreThanMaxDuration_StartTimeTooEarly_ReturnsMinusOne() { + let sut = fixture.sut + sut.start() + + let (startSystemTime, _, _) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) + + let endSystemTime = fixture.dateProvider.systemTime() + + 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.") + } + + func testFrameDelay_FramesTrackerNotRunning_ReturnsMinusOne() { + let sut = fixture.sut + sut.start() + + let startSystemTime = fixture.dateProvider.systemTime() + + let displayLink = fixture.displayLinkWrapper + displayLink.call() + _ = displayLink.slowestSlowFrame() + + let endSystemTime = fixture.dateProvider.systemTime() + + sut.stop() + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay) == -1.0 + } + + func testFrameDelay_RestartTracker_ReturnsMinusOne() { + let sut = fixture.sut + sut.start() + + let (startSystemTime, _, _) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) + + sut.stop() + sut.start() + + let endSystemTime = fixture.dateProvider.systemTime() + + let actualFrameDelay = sut.getFramesDelay(startSystemTime, endSystemTimestamp: endSystemTime) + expect(actualFrameDelay) == -1.0 + } + + func testFrameDelay_GetInfoFromBackgroundThreadWhileAdding() { + let sut = fixture.sut + sut.start() + + let (startSystemTime, _, _) = givenMoreDelayedFramesThanTransactionMaxDuration(sut) + 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() + } + } + + _ = givenMoreDelayedFramesThanTransactionMaxDuration(sut) + + wait(for: [expectation], timeout: 3.0) + } func testAddListener() { let sut = fixture.sut @@ -193,14 +536,36 @@ class SentryFramesTrackerTests: XCTestCase { } func testDealloc_CallsStop() { - func sutIsDeallocatedAfterCallingMe() { - _ = SentryFramesTracker(displayLinkWrapper: fixture.displayLinkWrapper) + _ = SentryFramesTracker(displayLinkWrapper: fixture.displayLinkWrapper, dateProvider: fixture.dateProvider, keepDelayedFramesDuration: 0) } sutIsDeallocatedAfterCallingMe() XCTAssertEqual(1, fixture.displayLinkWrapper.invalidateInvocations.count) } + + private func givenMoreDelayedFramesThanTransactionMaxDuration(_ framesTracker: SentryFramesTracker) -> (UInt64, UInt, Double) { + let displayLink = fixture.displayLinkWrapper + displayLink.call() + + 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 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.slowestSlowFrameDuration), slowFramesCount, slowFramesDelay) + } } private class FrameTrackerListener: NSObject, SentryFramesTrackerListener { 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() diff --git a/Tests/SentryTests/Transaction/SentryTracerTests.swift b/Tests/SentryTests/Transaction/SentryTracerTests.swift index 93efca9723f..122d04d3bf4 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() @@ -1059,37 +1060,70 @@ 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 extra = serializedTransaction["extra"] as? [String: Any] + + let framesDelay = extra?["frames.delay"] as? NSNumber + expect(framesDelay).to(beCloseTo(0.0, within: 0.0001)) } 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 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 - XCTAssertEqual([ - "frames_total": ["value": totalFrames], - "frames_slow": ["value": slowFrames], - "frames_frozen": ["value": frozenFrames] - ], measurements) - XCTAssertNil(SentrySDK.getAppStartMeasurement()) + expect(framesDelay).to(beCloseTo(expectedDelay, within: 0.0001)) + 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 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() {