fix: always report a frame rate with GPU profiler metrics (#2929)

In cases where subsequent concurrent transactions will contain slow/frozen GPU frame metrics for profiles, but the frame rate would have already been recorded for the first concurrent transaction, the profile payloads for the subsequent ones would have discarded the earlier frame rate data in slicing.

This makes sure the current frame rate is reported for such cases, instead of nothing.

CHANGELOG.md

@@ -1,5 +1,11 @@
 # Changelog
 
+## Unreleased
+
+### Fixes 
+
+- Ensure the current GPU frame rate is always reported for concurrent transaction profiling metrics (#2929)
+
 ## 8.5.0
 
 ### Features

Sources/Sentry/SentryFramesTracker.m

@@ -146,22 +146,18 @@ - (void)displayLinkCallback
     }
 
 #    if SENTRY_TARGET_PROFILING_SUPPORTED
-#        if defined(TEST) || defined(TESTCI)
-    BOOL shouldRecordFrameRates = YES;
-#        else
-    BOOL shouldRecordFrameRates = [SentryProfiler isRunning];
-#        endif // defined(TEST) || defined(TESTCI)
-    BOOL hasNoFrameRatesYet = self.frameRateTimestamps.count == 0;
-    uint64_t previousFrameRate
-        = self.frameRateTimestamps.lastObject[@"value"].unsignedLongLongValue;
-    BOOL frameRateChanged = previousFrameRate != currentFrameRate;
-    BOOL shouldRecordNewFrameRate
-        = shouldRecordFrameRates && (hasNoFrameRatesYet || frameRateChanged);
-    if (shouldRecordNewFrameRate) {
-        SENTRY_LOG_DEBUG(@"Recording new frame rate at %llu.", thisFrameSystemTimestamp);
-        [self recordTimestamp:thisFrameSystemTimestamp
-                        value:@(currentFrameRate)
-                        array:self.frameRateTimestamps];
+    if ([SentryProfiler isRunning]) {
+        BOOL hasNoFrameRatesYet = self.frameRateTimestamps.count == 0;
+        uint64_t previousFrameRate
+            = self.frameRateTimestamps.lastObject[@"value"].unsignedLongLongValue;
+        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)
+                            array:self.frameRateTimestamps];
+        }
     }
 #    endif // SENTRY_TARGET_PROFILING_SUPPORTED
 

Sources/Sentry/SentryProfiler.mm

@@ -192,11 +192,19 @@
  * Convert the data structure that records timestamps for GPU frame render info from
  * SentryFramesTracker to the structure expected for profiling metrics, and throw out any that
  * didn't occur within the profile time.
+ * @param useMostRecentRecording @c SentryFramesTracker doesn't stop running once it starts.
+ * Although we reset the profiling timestamps each time the profiler stops and starts, concurrent
+ * transactions that start after the first one won't have a screen frame rate recorded within their
+ * timeframe, because it will have already been recorded for the first transaction and isn't
+ * recorded again unless the system changes it. In these cases, use the most recently recorded data
+ * for it.
  */
 NSArray<SentrySerializedMetricReading *> *
-sliceGPUData(SentryFrameInfoTimeSeries *frameInfo, SentryTransaction *transaction)
+sliceGPUData(SentryFrameInfoTimeSeries *frameInfo, SentryTransaction *transaction,
+    BOOL useMostRecentRecording)
 {
     auto slicedGPUEntries = [NSMutableArray<SentrySerializedMetricEntry *> array];
+    __block NSNumber *nearestPredecessorValue;
     [frameInfo enumerateObjectsUsingBlock:^(
         NSDictionary<NSString *, NSNumber *> *_Nonnull obj, NSUInteger idx, BOOL *_Nonnull stop) {
         const auto timestamp = obj[@"timestamp"].unsignedLongLongValue;
@@ -205,6 +213,7 @@
             SENTRY_LOG_DEBUG(@"GPU info recorded (%llu) before transaction start (%llu), "
                              @"will not report it.",
                 timestamp, transaction.startSystemTime);
+            nearestPredecessorValue = obj[@"value"];
             return;
         }
 
@@ -219,6 +228,12 @@
             @"value" : obj[@"value"],
         }];
     }];
+    if (useMostRecentRecording && slicedGPUEntries.count == 0) {
+        [slicedGPUEntries addObject:@ {
+            @"elapsed_since_start_ns" : serializedUnsigned64BitInteger(0),
+            @"value" : nearestPredecessorValue,
+        }];
+    }
     return slicedGPUEntries;
 }
 #    endif // SENTRY_HAS_UIKIT
@@ -388,21 +403,23 @@ + (SentryEnvelopeItem *)createProfilingEnvelopeItemForTransaction:(SentryTransac
     const auto metrics = [_gCurrentProfiler->_metricProfiler serializeForTransaction:transaction];
 
 #    if SENTRY_HAS_UIKIT
-    const auto slowFrames
-        = sliceGPUData(_gCurrentFramesTracker.currentFrames.slowFrameTimestamps, transaction);
+    const auto slowFrames = sliceGPUData(_gCurrentFramesTracker.currentFrames.slowFrameTimestamps,
+        transaction, /*useMostRecentRecording */ NO);
     if (slowFrames.count > 0) {
         metrics[@"slow_frame_renders"] = @{ @"unit" : @"nanosecond", @"values" : slowFrames };
     }
 
     const auto frozenFrames
-        = sliceGPUData(_gCurrentFramesTracker.currentFrames.frozenFrameTimestamps, transaction);
+        = sliceGPUData(_gCurrentFramesTracker.currentFrames.frozenFrameTimestamps, transaction,
+            /*useMostRecentRecording */ NO);
     if (frozenFrames.count > 0) {
         metrics[@"frozen_frame_renders"] = @{ @"unit" : @"nanosecond", @"values" : frozenFrames };
     }
 
     if (slowFrames.count > 0 || frozenFrames.count > 0) {
         const auto frameRates
-            = sliceGPUData(_gCurrentFramesTracker.currentFrames.frameRateTimestamps, transaction);
+            = sliceGPUData(_gCurrentFramesTracker.currentFrames.frameRateTimestamps, transaction,
+                /*useMostRecentRecording */ YES);
         if (frameRates.count > 0) {
             metrics[@"screen_frame_rates"] = @{ @"unit" : @"hz", @"values" : frameRates };
         }

Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift

@@ -259,7 +259,6 @@ class SentryProfilerSwiftTests: XCTestCase {
         spans.removeAll()
 #if !os(macOS)
         fixture.resetGPUExpectations()
-        fixture.framesTracker.resetFrames()
         fixture.displayLinkWrapper.call()
 #endif
 

Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift

@@ -22,6 +22,18 @@ class SentryFramesTrackerTests: XCTestCase {
     override func setUp() {
         super.setUp()
         fixture = Fixture()
+
+#if os(iOS) || os(macOS) || targetEnvironment(macCatalyst)
+        // the profiler must be running for the frames tracker to record frame rate info etc, validated in assertProfilingData()
+        SentryProfiler.start(with: TestHub(client: nil, andScope: nil))
+#endif
+    }
+
+    override func tearDown() {
+        super.tearDown()
+#if os(iOS) || os(macOS) || targetEnvironment(macCatalyst)
+        SentryProfiler.stop()
+#endif
     }
 
     func testIsNotRunning_WhenNotStarted() {