Skip to content

Commit

Permalink
feat: Add frames delay to transactions (#3487)
Browse files Browse the repository at this point in the history
Add frames delay as span data to transactions.
  • Loading branch information
philipphofmann committed Dec 14, 2023
1 parent f25febb commit de033da
Show file tree
Hide file tree
Showing 17 changed files with 847 additions and 61 deletions.
1 change: 1 addition & 0 deletions CHANGELOG.md
Expand Up @@ -4,6 +4,7 @@

## Features

- Add frames delay to transactions (#3487)
- Add slow and frozen frames to spans (#3450, #3478)

## 8.17.1
Expand Down
16 changes: 16 additions & 0 deletions Sentry.xcodeproj/project.pbxproj
Expand Up @@ -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 */; };
Expand All @@ -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 */; };
Expand Down Expand Up @@ -995,6 +999,8 @@
623C45AE2A651C4500D9E88B /* SentryCoreDataTracker+Test.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = "SentryCoreDataTracker+Test.h"; sourceTree = "<group>"; };
623C45AF2A651D8200D9E88B /* SentryCoreDataTracker+Test.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = "SentryCoreDataTracker+Test.m"; sourceTree = "<group>"; };
627E7588299F6FE40085504D /* SentryInternalDefines.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryInternalDefines.h; path = include/SentryInternalDefines.h; sourceTree = "<group>"; };
62862B1B2B1DDBC8009B16E3 /* SentryDelayedFrame.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryDelayedFrame.h; path = include/SentryDelayedFrame.h; sourceTree = "<group>"; };
62862B1D2B1DDC35009B16E3 /* SentryDelayedFrame.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryDelayedFrame.m; sourceTree = "<group>"; };
62885DA629E946B100554F38 /* TestConncurrentModifications.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = TestConncurrentModifications.swift; sourceTree = "<group>"; };
62950F0F29E7FE0100A42624 /* SentryTransactionContextTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryTransactionContextTests.swift; sourceTree = "<group>"; };
629690522AD3E060000185FA /* SentryReachabilitySwiftTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryReachabilitySwiftTests.swift; sourceTree = "<group>"; };
Expand All @@ -1004,6 +1010,8 @@
62B86CFB29F052BB008F3947 /* SentryTestLogConfig.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryTestLogConfig.m; sourceTree = "<group>"; };
62C25C852B075F4900C68CBD /* TestOptions.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = TestOptions.swift; sourceTree = "<group>"; };
62C3168A2B1F865A000D7031 /* SentryTimeSwiftTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryTimeSwiftTests.swift; sourceTree = "<group>"; };
62C316802B1F2E93000D7031 /* SentryDelayedFramesTracker.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryDelayedFramesTracker.h; path = include/SentryDelayedFramesTracker.h; sourceTree = "<group>"; };
62C316822B1F2EA1000D7031 /* SentryDelayedFramesTracker.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryDelayedFramesTracker.m; sourceTree = "<group>"; };
62E081A829ED4260000F69FC /* SentryBreadcrumbDelegate.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryBreadcrumbDelegate.h; path = include/SentryBreadcrumbDelegate.h; sourceTree = "<group>"; };
62E081AA29ED4322000F69FC /* SentryBreadcrumbTestDelegate.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SentryBreadcrumbTestDelegate.swift; sourceTree = "<group>"; };
62F226B629A37C120038080D /* SentryBooleanSerialization.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentryBooleanSerialization.m; sourceTree = "<group>"; };
Expand Down Expand Up @@ -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 = "<group>";
Expand Down Expand Up @@ -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 */,
Expand Down Expand Up @@ -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 */,
Expand Down Expand Up @@ -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 */,
Expand Down Expand Up @@ -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 */,
Expand Down
8 changes: 4 additions & 4 deletions 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
Expand All @@ -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
Expand Down
25 changes: 25 additions & 0 deletions 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
196 changes: 196 additions & 0 deletions 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<SentryDelayedFrame *> *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<SentryDelayedFrame *> *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
5 changes: 4 additions & 1 deletion Sources/Sentry/SentryDependencyContainer.m
Expand Up @@ -26,6 +26,7 @@
#import <SentrySwizzleWrapper.h>
#import <SentrySysctl.h>
#import <SentryThreadWrapper.h>
#import <SentryTracer.h>

#if SENTRY_HAS_UIKIT
# import "SentryFramesTracker.h"
Expand Down Expand Up @@ -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];
}
}
}
Expand Down

0 comments on commit de033da

Please sign in to comment.