getsentry · armcknight · Oct 4, 2022 · Sep 26, 2022 · Sep 26, 2022 · Oct 4, 2022
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -5,6 +5,7 @@
 ### Fixes
 
 - Return SentryNoOpSpan when starting a child on a finished transaction (#2239)
+- Fix profiling timestamps for slow/frozen frames (#2226)
 
 ## 7.27.0
 

diff --git a/Sources/Sentry/SentryBacktrace.cpp b/Sources/Sentry/SentryBacktrace.cpp
@@ -19,9 +19,6 @@
 using namespace sentry::profiling;
 using namespace sentry::profiling::thread;
 
-#    define LIKELY(x) __builtin_expect(!!(x), 1)
-#    define UNLIKELY(x) __builtin_expect(!!(x), 0)
-
 namespace {
 ALWAYS_INLINE bool
 isValidFrame(std::uintptr_t frame, const StackBounds &bounds)

diff --git a/Sources/Sentry/SentryFramesTracker.m b/Sources/Sentry/SentryFramesTracker.m
@@ -1,4 +1,5 @@
 #import "SentryFramesTracker.h"
+#import "SentryCompiler.h"
 #import "SentryDisplayLinkWrapper.h"
 #import "SentryProfilingConditionals.h"
 #import "SentryTracer.h"
@@ -102,10 +103,10 @@ - (void)start
 
 - (void)displayLinkCallback
 {
-    CFTimeInterval lastFrameTimestamp = self.displayLinkWrapper.timestamp;
+    CFTimeInterval thisFrameTimestamp = self.displayLinkWrapper.timestamp;
 
     if (self.previousFrameTimestamp == SentryPreviousFrameInitialValue) {
-        self.previousFrameTimestamp = lastFrameTimestamp;
+        self.previousFrameTimestamp = thisFrameTimestamp;
         return;
     }
 
@@ -118,50 +119,67 @@ - (void)displayLinkCallback
     // 60 fps.
     double actualFramesPerSecond = 60.0;
     if (@available(iOS 10.0, tvOS 10.0, *)) {
-        actualFramesPerSecond
-            = 1 / (self.displayLinkWrapper.targetTimestamp - self.displayLinkWrapper.timestamp);
+        if (UNLIKELY(
+                (self.displayLinkWrapper.targetTimestamp == self.displayLinkWrapper.timestamp))) {
+            actualFramesPerSecond = 60.0;
+        } else {
+            actualFramesPerSecond
+                = 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)) {
+#        if defined(TEST) || defined(TESTCI)
+    BOOL shouldRecordFrameRates = YES;
+#        else
+    BOOL shouldRecordFrameRates = self.currentTracer.isProfiling;
+#        endif // defined(TEST) || defined(TESTCI)
+    BOOL hasNoFrameRatesYet = self.frameRateTimestamps.count == 0;
+    BOOL frameRateSignificantlyChanged
+        = fabs(self.frameRateTimestamps.lastObject[@"frame_rate"].doubleValue
+              - actualFramesPerSecond)
+        > 1e-10f; // these may be a small fraction off of a whole number of frames per second, so
+                  // allow some small epsilon difference
+    BOOL shouldRecordNewFrameRate
+        = shouldRecordFrameRates && (hasNoFrameRatesYet || frameRateSignificantlyChanged);
+    if (shouldRecordNewFrameRate) {
         [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.
+    // Most frames take just a few microseconds longer than the optimal calculated duration.
+    // Therefore we subtract one, because otherwise almost all frames would be slow.
     CFTimeInterval slowFrameThreshold = 1 / (actualFramesPerSecond - 1);
 
-    CFTimeInterval frameDuration = lastFrameTimestamp - self.previousFrameTimestamp;
-    self.previousFrameTimestamp = lastFrameTimestamp;
+    CFTimeInterval frameDuration = thisFrameTimestamp - self.previousFrameTimestamp;
 
     if (frameDuration > slowFrameThreshold && frameDuration <= SentryFrozenFrameThreshold) {
         atomic_fetch_add_explicit(&_slowFrames, 1, SentryFramesMemoryOrder);
 #    if SENTRY_TARGET_PROFILING_SUPPORTED
-        [self recordTimestampStart:@(self.previousFrameTimestamp) end:@(lastFrameTimestamp)];
+        [self recordTimestampStart:@(self.previousFrameTimestamp) end:@(thisFrameTimestamp)];
 #    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)];
+        [self recordTimestampStart:@(self.previousFrameTimestamp) end:@(thisFrameTimestamp)];
 #    endif // SENTRY_TARGET_PROFILING_SUPPORTED
     }
 
     atomic_fetch_add_explicit(&_totalFrames, 1, SentryFramesMemoryOrder);
-
-    self.previousFrameTimestamp = lastFrameTimestamp;
+    self.previousFrameTimestamp = thisFrameTimestamp;
 }
 
 #    if SENTRY_TARGET_PROFILING_SUPPORTED
 - (void)recordTimestampStart:(NSNumber *)start end:(NSNumber *)end
 {
-    if (self.currentTracer.isProfiling) {
+    BOOL shouldRecord = self.currentTracer.isProfiling;
+#        if defined(TEST) || defined(TESTCI)
+    shouldRecord = YES;
+#        endif
+    if (shouldRecord) {
         [self.frameTimestamps addObject:@{ @"start_timestamp" : start, @"end_timestamp" : end }];
     }
 }

diff --git a/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/FramesTracking/SentryFramesTrackerTests.swift
@@ -13,9 +13,9 @@ class SentryFramesTrackerTests: XCTestCase {
             queue = DispatchQueue(label: "SentryFramesTrackerTests", qos: .background, attributes: [.concurrent])
         }
 
-        var sut: SentryFramesTracker {
+        lazy var sut: SentryFramesTracker = {
             return SentryFramesTracker(displayLinkWrapper: displayLinkWrapper)
-        }
+        }()
     }
 
     private var fixture: Fixture!
@@ -50,11 +50,8 @@ class SentryFramesTrackerTests: XCTestCase {
         fixture.displayLinkWrapper.slowFrame()
         fixture.displayLinkWrapper.normalFrame()
         fixture.displayLinkWrapper.almostFrozenFrame()
-
-        let currentFrames = sut.currentFrames
-        XCTAssertEqual(2, currentFrames.slow)
-        XCTAssertEqual(3, currentFrames.total)
-        XCTAssertEqual(0, currentFrames.frozen)
+
+        assert(slow: 2, frozen: 0, total: 3)
     }
 
     func testFrozenFrame() {
@@ -64,23 +61,20 @@ class SentryFramesTrackerTests: XCTestCase {
         fixture.displayLinkWrapper.call()
         fixture.displayLinkWrapper.slowFrame()
         fixture.displayLinkWrapper.frozenFrame()
-
-        let currentFrames = sut.currentFrames
-        XCTAssertEqual(1, currentFrames.slow)
-        XCTAssertEqual(2, currentFrames.total)
-        XCTAssertEqual(1, currentFrames.frozen)
+
+        assert(slow: 1, frozen: 1, total: 2)
     }
 
     func testAllFrames_ConcurrentRead() {
         let sut = fixture.sut
         sut.start()
 
         let group = DispatchGroup()
-        
-        var currentFrames = sut.currentFrames
-        assertPreviousCountBiggerThanCurrent(group) { return currentFrames.frozen }
-        assertPreviousCountBiggerThanCurrent(group) { return currentFrames.slow }
-        assertPreviousCountBiggerThanCurrent(group) { return currentFrames.total }
+
+        let currentFrames = sut.currentFrames
+        assertPreviousCountLesserThanCurrent(group) { return currentFrames.frozen }
+        assertPreviousCountLesserThanCurrent(group) { return currentFrames.slow }
+        assertPreviousCountLesserThanCurrent(group) { return currentFrames.total }
 
         fixture.displayLinkWrapper.call()
 
@@ -92,10 +86,7 @@ class SentryFramesTrackerTests: XCTestCase {
         }
 
         group.wait()
-        currentFrames = sut.currentFrames
-        XCTAssertEqual(3 * frames, currentFrames.total)
-        XCTAssertEqual(frames, currentFrames.slow)
-        XCTAssertEqual(frames, currentFrames.frozen)
+        assert(slow: frames, frozen: frames, total: 3 * frames)
     }
 
     func testPerformanceOfTrackingFrames() {
@@ -108,12 +99,35 @@ class SentryFramesTrackerTests: XCTestCase {
                 fixture.displayLinkWrapper.normalFrame()
             }
         }
-
-        XCTAssertEqual(0, sut.currentFrames.slow)
-        XCTAssertEqual(0, sut.currentFrames.frozen)
+
+        assert(slow: 0, frozen: 0)
     }
-
-    private func assertPreviousCountBiggerThanCurrent(_ group: DispatchGroup, count: @escaping () -> UInt) {
+}
+
+private extension SentryFramesTrackerTests {
+    func assert(slow: UInt? = nil, frozen: UInt? = nil, total: UInt? = nil) {
+        let currentFrames = fixture.sut.currentFrames
+        if let total = total {
+            XCTAssertEqual(total, currentFrames.total)
+        }
+        if let slow = slow {
+            XCTAssertEqual(slow, currentFrames.slow)
+        }
+        if let frozen = frozen {
+            XCTAssertEqual(frozen, currentFrames.frozen)
+        }
+#if SENTRY_TARGET_PROFILING_SUPPORTED
+        if ((slow ?? 0) + (frozen ?? 0)) > 0 {
+            XCTAssertGreaterThan(currentFrames.frameTimestamps.count, 0)
+            for frame in currentFrames.frameTimestamps {
+                XCTAssertFalse(frame["start_timestamp"] == frame["end_timestamp"])
+            }
+        }
+        XCTAssertGreaterThan(currentFrames.frameRateTimestamps.count, 0)
+#endif
+    }
+
+    private func assertPreviousCountLesserThanCurrent(_ group: DispatchGroup, count: @escaping () -> UInt) {
         group.enter()
         fixture.queue.async {
             var previousCount: UInt = 0
@@ -125,7 +139,6 @@ class SentryFramesTrackerTests: XCTestCase {
             group.leave()
         }
     }
-
 }
 
 #endif