feat: upload list of slow/frozen rendered frame timestamps during a p…

…rofile (#1910) * reset timestamps for each profiled transaction * convert timestamps to be relative to transaction start in nanoseconds * also send time series of refresh rate changes during profiled transactions * move all possible logic to first locked profiler sector in finishInternal; move early bail for hub nil check earlier Co-authored-by: Philipp Hofmann <philipp.hofmann@sentry.io> Co-authored-by: Sentry Github Bot <bot+github-bot@sentry.io>
getsentry · Jul 13, 2022 · c0397aa · c0397aa
1 parent e65226c
commit c0397aa
Show file tree

Hide file tree

Showing 10 changed files with 217 additions and 13 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -7,6 +7,7 @@
 - Enhance the UIViewController breadcrumbs with more data (#1945)
 - feat: Add extra app start span (#1952)
 - Add enableAutoBreadcrumbTracking option (#1958)
+- Upload frame rendering timestamps to correlate to sampled backtraces (#1910)
 
 ### Fixes
 

diff --git a/Sentry.xcodeproj/project.pbxproj b/Sentry.xcodeproj/project.pbxproj
@@ -3041,7 +3041,7 @@
 				TargetAttributes = {
 					63AA759A1EB8AEF500D153DE = {
 						CreatedOnToolsVersion = 8.3.2;
-						LastSwiftMigration = 1330;
+						LastSwiftMigration = 1340;
 						ProvisioningStyle = Manual;
 					};
 					63AA76641EB8CB2F00D153DE = {

diff --git a/Sources/Sentry/Public/SentryScreenFrames.h b/Sources/Sentry/Public/SentryScreenFrames.h
@@ -1,18 +1,47 @@
 #import "SentryDefines.h"
+#import "SentryProfilingConditionals.h"
 
 NS_ASSUME_NONNULL_BEGIN
 
 #if SENTRY_HAS_UIKIT
 
+/** An array of dictionaries that each contain a start and end timestamp for a rendered frame. */
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+typedef NSArray<NSDictionary<NSString *, NSNumber *> *> SentryFrameInfoTimeSeries;
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
+
 @interface SentryScreenFrames : NSObject
 SENTRY_NO_INIT
 
 - (instancetype)initWithTotal:(NSUInteger)total frozen:(NSUInteger)frozen slow:(NSUInteger)slow;
 
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+- (instancetype)initWithTotal:(NSUInteger)total
+                       frozen:(NSUInteger)frozen
+                         slow:(NSUInteger)slow
+              frameTimestamps:(SentryFrameInfoTimeSeries *)frameTimestamps
+          frameRateTimestamps:(SentryFrameInfoTimeSeries *)frameRateTimestamps;
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
+
 @property (nonatomic, assign, readonly) NSUInteger total;
 @property (nonatomic, assign, readonly) NSUInteger frozen;
 @property (nonatomic, assign, readonly) NSUInteger slow;
 
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+/**
+ * Array of dictionaries describing slow/frozen frames' timestamps. Each dictionary start and end
+ * timestamp for every such frame, keyed under @c start_timestamp and @c end_timestamp.
+ */
+@property (nonatomic, copy, readonly) SentryFrameInfoTimeSeries *frameTimestamps;
+
+/**
+ * Array of dictionaries describing the screen refresh rate at all points in time that it changes,
+ * which can happen when modern devices e.g. go into low power mode. Each dictionary contains keys
+ * @c timestamp and @c frame_rate.
+ */
+@property (nonatomic, copy, readonly) SentryFrameInfoTimeSeries *frameRateTimestamps;
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
+
 @end
 
 #endif

diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m
@@ -1,12 +1,18 @@
 #import "SentryFramesTracker.h"
 #import "SentryDisplayLinkWrapper.h"
-#import <SentryLog.h>
+#import "SentryProfilingConditionals.h"
+#import "SentryTracer.h"
 #import <SentryScreenFrames.h>
 #include <stdatomic.h>
 
 #if SENTRY_HAS_UIKIT
 #    import <UIKit/UIKit.h>
 
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+/** A mutable version of @c SentryFrameInfoTimeSeries so we can accumulate results. */
+typedef NSMutableArray<NSDictionary<NSString *, NSNumber *> *> SentryMutableFrameInfoTimeSeries;
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
+
 static CFTimeInterval const SentryFrozenFrameThreshold = 0.7;
 static CFTimeInterval const SentryPreviousFrameInitialValue = -1;
 
@@ -21,6 +27,10 @@
 
 @property (nonatomic, strong, readonly) SentryDisplayLinkWrapper *displayLinkWrapper;
 @property (nonatomic, assign) CFTimeInterval previousFrameTimestamp;
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+@property (nonatomic, readwrite) SentryMutableFrameInfoTimeSeries *frameTimestamps;
+@property (nonatomic, readwrite) SentryMutableFrameInfoTimeSeries *frameRateTimestamps;
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
 
 @end
 
@@ -71,7 +81,18 @@ - (void)resetFrames
     atomic_store_explicit(&_slowFrames, 0, SentryFramesMemoryOrder);
 
     self.previousFrameTimestamp = SentryPreviousFrameInitialValue;
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+    [self resetProfilingTimestamps];
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
+}
+
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+- (void)resetProfilingTimestamps
+{
+    self.frameTimestamps = [SentryMutableFrameInfoTimeSeries array];
+    self.frameRateTimestamps = [SentryMutableFrameInfoTimeSeries array];
 }
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
 
 - (void)start
 {
@@ -101,6 +122,18 @@ - (void)displayLinkCallback
             = 1 / (self.displayLinkWrapper.targetTimestamp - self.displayLinkWrapper.timestamp);
     }
 
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+    if (self.currentTracer.isProfiling
+        && (self.frameRateTimestamps.count == 0
+            || self.frameRateTimestamps.lastObject[@"frame_rate"].doubleValue
+                != actualFramesPerSecond)) {
+        [self.frameRateTimestamps addObject:@{
+            @"timestamp" : @(self.displayLinkWrapper.timestamp),
+            @"frame_rate" : @(actualFramesPerSecond),
+        }];
+    }
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
+
     // Most frames take just a few microseconds longer than the optimal caculated duration.
     // Therefore we substract one, because otherwise almost all frames would be slow.
     CFTimeInterval slowFrameThreshold = 1 / (actualFramesPerSecond - 1);
@@ -110,22 +143,45 @@ - (void)displayLinkCallback
 
     if (frameDuration > slowFrameThreshold && frameDuration <= SentryFrozenFrameThreshold) {
         atomic_fetch_add_explicit(&_slowFrames, 1, SentryFramesMemoryOrder);
-    }
-
-    if (frameDuration > SentryFrozenFrameThreshold) {
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+        [self recordTimestampStart:@(self.previousFrameTimestamp) end:@(lastFrameTimestamp)];
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
+    } else if (frameDuration > SentryFrozenFrameThreshold) {
         atomic_fetch_add_explicit(&_frozenFrames, 1, SentryFramesMemoryOrder);
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+        [self recordTimestampStart:@(self.previousFrameTimestamp) end:@(lastFrameTimestamp)];
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
     }
 
     atomic_fetch_add_explicit(&_totalFrames, 1, SentryFramesMemoryOrder);
+
+    self.previousFrameTimestamp = lastFrameTimestamp;
+}
+
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+- (void)recordTimestampStart:(NSNumber *)start end:(NSNumber *)end
+{
+    if (self.currentTracer.isProfiling) {
+        [self.frameTimestamps addObject:@{ @"start_timestamp" : start, @"end_timestamp" : end }];
+    }
 }
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
 
 - (SentryScreenFrames *)currentFrames
 {
     NSUInteger total = atomic_load_explicit(&_totalFrames, SentryFramesMemoryOrder);
     NSUInteger slow = atomic_load_explicit(&_slowFrames, SentryFramesMemoryOrder);
     NSUInteger frozen = atomic_load_explicit(&_frozenFrames, SentryFramesMemoryOrder);
 
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+    return [[SentryScreenFrames alloc] initWithTotal:total
+                                              frozen:frozen
+                                                slow:slow
+                                     frameTimestamps:self.frameTimestamps
+                                 frameRateTimestamps:self.frameRateTimestamps];
+#    else
     return [[SentryScreenFrames alloc] initWithTotal:total frozen:frozen slow:slow];
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
 }
 
 - (void)stop

diff --git a/Sources/Sentry/SentryProfiler.mm b/Sources/Sentry/SentryProfiler.mm
@@ -9,11 +9,13 @@
 #    import "SentryDependencyContainer.h"
 #    import "SentryEnvelope.h"
 #    import "SentryEnvelopeItemType.h"
+#    import "SentryFramesTracker.h"
 #    import "SentryHexAddressFormatter.h"
 #    import "SentryId.h"
 #    import "SentryLog.h"
 #    import "SentryProfilingLogging.hpp"
 #    import "SentrySamplingProfiler.hpp"
+#    import "SentryScreenFrames.h"
 #    import "SentrySerialization.h"
 #    import "SentryTime.h"
 #    import "SentryTransaction.h"
@@ -208,6 +210,7 @@ - (void)stop
 }
 
 - (SentryEnvelopeItem *)buildEnvelopeItemForTransaction:(SentryTransaction *)transaction
+                                              frameInfo:(SentryScreenFrames *)frameInfo
 {
     NSMutableDictionary<NSString *, id> *profile = nil;
     @synchronized(self) {
@@ -253,6 +256,39 @@ - (SentryEnvelopeItem *)buildEnvelopeItemForTransaction:(SentryTransaction *)tra
     profile[@"version_code"] = [bundle objectForInfoDictionaryKey:(NSString *)kCFBundleVersionKey];
     profile[@"version_name"] = [bundle objectForInfoDictionaryKey:@"CFBundleShortVersionString"];
 
+#    if SENTRY_HAS_UIKIT
+    auto relativeFrameTimestampsNs = [NSMutableArray array];
+    [frameInfo.frameTimestamps enumerateObjectsUsingBlock:^(
+        NSDictionary<NSString *, NSNumber *> *_Nonnull obj, NSUInteger idx, BOOL *_Nonnull stop) {
+        const auto begin = (uint64_t)(obj[@"start_timestamp"].doubleValue * 1e9);
+        if (begin < _startTimestamp) {
+            return;
+        }
+        const auto end = (uint64_t)(obj[@"end_timestamp"].doubleValue * 1e9);
+        [relativeFrameTimestampsNs addObject:@{
+            @"start_timestamp_relative_ns" : @(getDurationNs(_startTimestamp, begin)),
+            @"end_timestamp_relative_ns" : @(getDurationNs(_startTimestamp, end)),
+        }];
+    }];
+    profile[@"adverse_frame_render_timestamps"] = relativeFrameTimestampsNs;
+
+    relativeFrameTimestampsNs = [NSMutableArray array];
+    [frameInfo.frameRateTimestamps enumerateObjectsUsingBlock:^(
+        NSDictionary<NSString *, NSNumber *> *_Nonnull obj, NSUInteger idx, BOOL *_Nonnull stop) {
+        const auto timestamp = (uint64_t)(obj[@"timestamp"].doubleValue * 1e9);
+        const auto refreshRate = obj[@"frame_rate"];
+        uint64_t relativeTimestamp = 0;
+        if (timestamp >= _startTimestamp) {
+            relativeTimestamp = getDurationNs(_startTimestamp, timestamp);
+        }
+        [relativeFrameTimestampsNs addObject:@{
+            @"start_timestamp_relative_ns" : @(relativeTimestamp),
+            @"frame_rate" : refreshRate,
+        }];
+    }];
+    profile[@"screen_frame_rates"] = relativeFrameTimestampsNs;
+#    endif // SENTRY_HAS_UIKIT
+
     NSError *error = nil;
     const auto JSONData = [SentrySerialization dataWithJSONObject:profile error:&error];
     if (JSONData == nil) {
@@ -268,6 +304,11 @@ - (SentryEnvelopeItem *)buildEnvelopeItemForTransaction:(SentryTransaction *)tra
     return [[SentryEnvelopeItem alloc] initWithHeader:header data:JSONData];
 }
 
+- (BOOL)isRunning
+{
+    return _profiler->isSampling();
+}
+
 @end
 
 #endif
diff --git a/Sources/Sentry/SentryScreenFrames.m b/Sources/Sentry/SentryScreenFrames.m
@@ -6,15 +6,42 @@ @implementation SentryScreenFrames
 
 - (instancetype)initWithTotal:(NSUInteger)total frozen:(NSUInteger)frozen slow:(NSUInteger)slow
 {
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+    return [self initWithTotal:total
+                        frozen:frozen
+                          slow:slow
+               frameTimestamps:@[]
+           frameRateTimestamps:@[]];
+#    else
     if (self = [super init]) {
         _total = total;
         _slow = slow;
         _frozen = frozen;
     }
 
     return self;
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
 }
 
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+- (instancetype)initWithTotal:(NSUInteger)total
+                       frozen:(NSUInteger)frozen
+                         slow:(NSUInteger)slow
+              frameTimestamps:(SentryFrameInfoTimeSeries *)frameTimestamps
+          frameRateTimestamps:(SentryFrameInfoTimeSeries *)frameRateTimestamps
+{
+    if (self = [super init]) {
+        _total = total;
+        _slow = slow;
+        _frozen = frozen;
+        _frameTimestamps = frameTimestamps;
+        _frameRateTimestamps = frameRateTimestamps;
+    }
+
+    return self;
+}
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
+
 @end
 
 #endif
diff --git a/Sources/Sentry/SentryTracer.m b/Sources/Sentry/SentryTracer.m
@@ -44,6 +44,7 @@
 @property (nonatomic) BOOL isWaitingForChildren;
 @property (nonatomic) NSTimeInterval idleTimeout;
 @property (nonatomic, nullable, strong) SentryDispatchQueueWrapper *dispatchQueueWrapper;
+@property (nonatomic, assign, readwrite) BOOL isProfiling;
 
 @end
 
@@ -147,18 +148,22 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti
             initSlowFrames = currentFrames.slow;
             initFrozenFrames = currentFrames.frozen;
         }
-#endif
+#endif // SENTRY_HAS_UIKIT
 #if SENTRY_TARGET_PROFILING_SUPPORTED
         if ([_hub getClient].options.enableProfiling) {
             [profilerLock lock];
             if (profiler == nil) {
                 profiler = [[SentryProfiler alloc] init];
                 [SentryLog logWithMessage:@"Starting profiler." andLevel:kSentryLevelDebug];
+#    if SENTRY_HAS_UIKIT
+                framesTracker.currentTracer = self;
+                [framesTracker resetProfilingTimestamps];
+#    endif // SENTRY_HAS_UIKIT
                 [profiler start];
             }
             [profilerLock unlock];
         }
-#endif
+#endif // SENTRY_TARGET_PROFILING_SUPPORTED
     }
 
     return self;
@@ -398,17 +403,23 @@ - (void)finishInternal
         self.finishCallback = nil;
     }
 
+    if (_hub == nil)
+        return;
+
 #if SENTRY_TARGET_PROFILING_SUPPORTED
+    SentryScreenFrames *frameInfo;
     if ([_hub getClient].options.enableProfiling) {
         [SentryLog logWithMessage:@"Stopping profiler." andLevel:kSentryLevelDebug];
         [profilerLock lock];
         [profiler stop];
+#    if SENTRY_HAS_UIKIT
+        frameInfo = SentryFramesTracker.sharedInstance.currentFrames;
+        [SentryFramesTracker.sharedInstance resetProfilingTimestamps];
+        SentryFramesTracker.sharedInstance.currentTracer = nil;
+#    endif // SENTRY_HAS_UIKIT
         [profilerLock unlock];
     }
-#endif
-
-    if (_hub == nil)
-        return;
+#endif // SENTRY_TARGET_PROFILING_SUPPORTED
 
     [_hub.scope useSpan:^(id<SentrySpan> _Nullable span) {
         if (span == self) {
@@ -453,11 +464,13 @@ - (void)finishInternal
     }
 
     NSMutableArray<SentryEnvelopeItem *> *additionalEnvelopeItems = [NSMutableArray array];
+
 #if SENTRY_TARGET_PROFILING_SUPPORTED
     if ([_hub getClient].options.enableProfiling) {
         [profilerLock lock];
         if (profiler != nil) {
-            SentryEnvelopeItem *profile = [profiler buildEnvelopeItemForTransaction:transaction];
+            SentryEnvelopeItem *profile = [profiler buildEnvelopeItemForTransaction:transaction
+                                                                          frameInfo:frameInfo];
             if (profile != nil) {
                 [additionalEnvelopeItems addObject:profile];
             }
@@ -734,6 +747,16 @@ + (nullable SentryTracer *)getTracer:(id<SentrySpan>)span
     return nil;
 }
 
+#if SENTRY_TARGET_PROFILING_SUPPORTED
+- (BOOL)isProfiling
+{
+    [profilerLock lock];
+    BOOL isRunning = profiler.isRunning;
+    [profilerLock unlock];
+    return isRunning;
+}
+#endif // SENTRY_TARGET_PROFILING_SUPPORTED
+
 @end
 
 NS_ASSUME_NONNULL_END