enhancement(frame-tracking): only store slow and frozen frames for ca…

…lculation (#2337) * update * update * update * update * update * wrap in try catch * update * Update span_frame_metrics_collector.dart * update * update
getsentry · Oct 10, 2024 · 6d50a9b · 6d50a9b
1 parent 20926fc
commit 6d50a9b
Show file tree

Hide file tree

Showing 3 changed files with 117 additions and 76 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -14,6 +14,7 @@
 - Improve app start integration ([#2266](https://github.com/getsentry/sentry-dart/pull/2266))
   - Fixes ([#2103](https://github.com/getsentry/sentry-dart/issues/2103))
   - Fixes ([#2233](https://github.com/getsentry/sentry-dart/issues/2233))
+- Only store slow and frozen frames for frame delay calculation ([#2337](https://github.com/getsentry/sentry-dart/pull/2337))
 
 ### Fixes
 

diff --git a/flutter/lib/src/span_frame_metrics_collector.dart b/flutter/lib/src/span_frame_metrics_collector.dart
@@ -11,7 +11,7 @@ import 'native/sentry_native_binding.dart';
 
 @internal
 class SpanFrameMetricsCollector implements PerformanceContinuousCollector {
-  static const _frozenFrameThresholdMs = 700;
+  static const _frozenFrameThreshold = Duration(milliseconds: 700);
   static const totalFramesKey = 'frames.total';
   static const framesDelayKey = 'frames.delay';
   static const slowFramesKey = 'frames.slow';
@@ -23,11 +23,11 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector {
 
   final bool _isTestMode;
 
-  /// Stores frame timestamps and their durations in milliseconds.
+  /// Stores timestamps and durations (in milliseconds) of frames exceeding the expected duration.
   /// Keys are frame timestamps, values are frame durations.
   /// The timestamps mark the end of the frame.
   @visibleForTesting
-  final frames = SplayTreeMap<DateTime, int>();
+  final exceededFrames = SplayTreeMap<DateTime, int>();
 
   /// Stores the spans that are actively being tracked.
   /// After the frames are calculated and stored in the span the span is removed from this list.
@@ -44,6 +44,9 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector {
   @visibleForTesting
   int? displayRefreshRate;
 
+  @visibleForTesting
+  Duration? expectedFrameDuration;
+
   @visibleForTesting
   int maxFramesToTrack = 10800;
 
@@ -59,47 +62,68 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector {
         _isTestMode = isTestMode;
 
   @override
-  Future<void> onSpanStarted(ISentrySpan span) async {
-    if (span is NoOpSentrySpan || !options.enableFramesTracking) {
-      return;
-    }
-
-    final fetchedDisplayRefreshRate = await _native?.displayRefreshRate();
-    if (fetchedDisplayRefreshRate != null && fetchedDisplayRefreshRate > 0) {
-      options.logger(SentryLevel.debug,
-          'Retrieved display refresh rate at $fetchedDisplayRefreshRate');
-      displayRefreshRate = fetchedDisplayRefreshRate;
-
-      // Start tracking frames only when refresh rate is valid
-      activeSpans.add(span);
-      startFrameTracking();
-    } else {
-      options.logger(SentryLevel.debug,
-          'Retrieved invalid display refresh rate: $fetchedDisplayRefreshRate. Not starting frame tracking.');
-    }
-  }
+  Future<void> onSpanStarted(ISentrySpan span) =>
+      _tryCatch('onSpanStarted', () async {
+        if (span is NoOpSentrySpan || !options.enableFramesTracking) {
+          return;
+        }
+
+        final fetchedDisplayRefreshRate = await _native?.displayRefreshRate();
+        if (fetchedDisplayRefreshRate != null &&
+            fetchedDisplayRefreshRate > 0) {
+          options.logger(SentryLevel.debug,
+              'Retrieved display refresh rate at $fetchedDisplayRefreshRate');
+          displayRefreshRate = fetchedDisplayRefreshRate;
+          expectedFrameDuration = Duration(
+              milliseconds: ((1 / fetchedDisplayRefreshRate) * 1000).toInt());
+
+          // Start tracking frames only when refresh rate is valid
+          activeSpans.add(span);
+          startFrameTracking();
+        } else {
+          options.logger(SentryLevel.debug,
+              'Retrieved invalid display refresh rate: $fetchedDisplayRefreshRate. Not starting frame tracking.');
+        }
+      });
 
   @override
-  Future<void> onSpanFinished(ISentrySpan span, DateTime endTimestamp) async {
-    if (span is NoOpSentrySpan || !activeSpans.contains(span)) return;
-
-    if (displayRefreshRate == null || displayRefreshRate! <= 0) {
-      options.logger(SentryLevel.warning,
-          'Invalid display refresh rate. Skipping frame tracking for all active spans.');
-      clear();
-      return;
-    }
-
-    final frameMetrics =
-        calculateFrameMetrics(span, endTimestamp, displayRefreshRate!);
-    _applyFrameMetricsToSpan(span, frameMetrics);
+  Future<void> onSpanFinished(ISentrySpan span, DateTime endTimestamp) =>
+      _tryCatch('onSpanFinished', () async {
+        if (span is NoOpSentrySpan || !activeSpans.contains(span)) return;
+
+        if (displayRefreshRate == null || displayRefreshRate! <= 0) {
+          options.logger(SentryLevel.warning,
+              'Invalid display refresh rate. Skipping frame tracking for all active spans.');
+          clear();
+          return;
+        }
+
+        final frameMetrics =
+            calculateFrameMetrics(span, endTimestamp, displayRefreshRate!);
+        _applyFrameMetricsToSpan(span, frameMetrics);
+
+        activeSpans.remove(span);
+        if (activeSpans.isEmpty) {
+          clear();
+        } else {
+          exceededFrames.removeWhere((frameTimestamp, _) =>
+              frameTimestamp.isBefore(activeSpans.first.startTimestamp));
+        }
+      });
 
-    activeSpans.remove(span);
-    if (activeSpans.isEmpty) {
+  // TODO: there's already a similar implementation: [SentryNativeSafeInvoker]
+  // let's try to reuse it at some point
+  Future<void> _tryCatch(String methodName, Future<void> Function() fn) async {
+    try {
+      return fn();
+    } catch (exception, stackTrace) {
+      options.logger(
+        SentryLevel.error,
+        'SpanFrameMetricsCollector $methodName failed',
+        exception: exception,
+        stackTrace: stackTrace,
+      );
       clear();
-    } else {
-      frames.removeWhere((frameTimestamp, _) =>
-          frameTimestamp.isBefore(activeSpans.first.startTimestamp));
     }
   }
 
@@ -117,21 +141,28 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector {
     }
   }
 
-  /// Records the duration of a single frame and stores it in [frames].
+  /// Records the duration of a single frame and stores it in [exceededFrames].
   ///
   /// This method is called for each frame when frame tracking is active.
   Future<void> measureFrameDuration(Duration duration) async {
-    if (frames.length >= maxFramesToTrack) {
+    if (exceededFrames.length >= maxFramesToTrack) {
       options.logger(SentryLevel.warning,
           'Frame tracking limit reached. Clearing frames and cancelling frame tracking for all active spans');
       clear();
       return;
     }
 
+    if (expectedFrameDuration == null) {
+      options.logger(SentryLevel.info,
+          'Expected frame duration is null. Cancelling frame tracking for all active spans.');
+      clear();
+      return;
+    }
+
     // Using the stopwatch to measure the frame duration is flaky in ci
     if (_isTestMode) {
       // ignore: invalid_use_of_internal_member
-      frames[options.clock().add(duration)] = duration.inMilliseconds;
+      exceededFrames[options.clock().add(duration)] = duration.inMilliseconds;
       return;
     }
 
@@ -144,8 +175,10 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector {
     await _frameCallbackHandler.endOfFrame;
 
     final frameDuration = _stopwatch.elapsedMilliseconds;
-    // ignore: invalid_use_of_internal_member
-    frames[options.clock()] = frameDuration;
+    if (frameDuration > expectedFrameDuration!.inMilliseconds) {
+      // ignore: invalid_use_of_internal_member
+      exceededFrames[options.clock()] = frameDuration;
+    }
 
     _stopwatch.reset();
 
@@ -177,21 +210,25 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector {
   @visibleForTesting
   Map<String, int> calculateFrameMetrics(
       ISentrySpan span, DateTime spanEndTimestamp, int displayRefreshRate) {
-    if (frames.isEmpty) {
+    if (exceededFrames.isEmpty) {
       options.logger(
           SentryLevel.info, 'No frame durations available in frame tracker.');
       return {};
     }
 
-    final expectedFrameDuration = ((1 / displayRefreshRate) * 1000).toInt();
+    if (expectedFrameDuration == null) {
+      options.logger(SentryLevel.info,
+          'Expected frame duration is null. Dropping frame metrics.');
+      return {};
+    }
 
     int slowFramesCount = 0;
     int frozenFramesCount = 0;
     int slowFramesDuration = 0;
     int frozenFramesDuration = 0;
     int framesDelay = 0;
 
-    for (final entry in frames.entries) {
+    for (final entry in exceededFrames.entries) {
       final frameDuration = entry.value;
       final frameEndTimestamp = entry.key;
       final frameStartMs =
@@ -214,27 +251,26 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector {
 
       if (frameFullyContainedInSpan) {
         effectiveDuration = frameDuration;
-        effectiveDelay = max(0, frameDuration - expectedFrameDuration);
+        effectiveDelay =
+            max(0, frameDuration - expectedFrameDuration!.inMilliseconds);
       } else if (framePartiallyContainedInSpan) {
         final intersectionStart = max(frameStartMs, spanStartMs);
         final intersectionEnd = min(frameEndMs, spanEndMs);
         effectiveDuration = intersectionEnd - intersectionStart;
 
-        final fullFrameDelay = max(0, frameDuration - expectedFrameDuration);
+        final fullFrameDelay =
+            max(0, frameDuration - expectedFrameDuration!.inMilliseconds);
         final intersectionRatio = effectiveDuration / frameDuration;
         effectiveDelay = (fullFrameDelay * intersectionRatio).round();
       } else if (frameStartMs > spanEndMs) {
         // Other frames will be newer than this span, as frames are ordered
         break;
-      } else {
-        // Frame is completely outside the span, skip it
-        continue;
       }
 
-      if (effectiveDuration > _frozenFrameThresholdMs) {
+      if (effectiveDuration >= _frozenFrameThreshold.inMilliseconds) {
         frozenFramesCount++;
         frozenFramesDuration += effectiveDuration;
-      } else if (effectiveDuration > expectedFrameDuration) {
+      } else if (effectiveDuration > expectedFrameDuration!.inMilliseconds) {
         slowFramesCount++;
         slowFramesDuration += effectiveDuration;
       }
@@ -246,7 +282,7 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector {
         spanEndTimestamp.difference(span.startTimestamp).inMilliseconds;
     final normalFramesCount =
         (spanDuration - (slowFramesDuration + frozenFramesDuration)) /
-            expectedFrameDuration;
+            expectedFrameDuration!.inMilliseconds;
     final totalFramesCount =
         (normalFramesCount + slowFramesCount + frozenFramesCount).ceil();
 
@@ -278,7 +314,7 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector {
   void clear() {
     _isTrackingPaused = true;
     _stopwatch.reset();
-    frames.clear();
+    exceededFrames.clear();
     activeSpans.clear();
     displayRefreshRate = null;
   }

diff --git a/flutter/test/span_frame_metrics_collector_test.dart b/flutter/test/span_frame_metrics_collector_test.dart
@@ -25,14 +25,14 @@ void main() {
 
   test('clear() clears frames, running spans and pauses frame tracking', () {
     final sut = fixture.sut;
-    sut.frames[DateTime.now()] = 1;
+    sut.exceededFrames[DateTime.now()] = 1;
     final mockSpan = MockSentrySpan();
     when(mockSpan.startTimestamp).thenReturn(DateTime.now());
 
     sut.onSpanStarted(mockSpan);
     sut.clear();
 
-    expect(sut.frames, isEmpty);
+    expect(sut.exceededFrames, isEmpty);
     expect(sut.activeSpans, isEmpty);
     expect(sut.isTrackingPaused, isTrue);
   });
@@ -84,7 +84,6 @@ void main() {
     final span2 = MockSentrySpan();
     final spanStartTimestamp = DateTime.now();
     final spanEndTimestamp = spanStartTimestamp.add(Duration(seconds: 1));
-    sut.displayRefreshRate = 60;
 
     when(span1.isRootSpan).thenReturn(false);
     when(span1.startTimestamp).thenReturn(spanStartTimestamp);
@@ -98,14 +97,15 @@ void main() {
     sut.activeSpans.add(span1);
     sut.activeSpans.add(span2);
 
-    sut.frames[spanStartTimestamp.subtract(Duration(seconds: 5))] = 1;
-    sut.frames[spanStartTimestamp.subtract(Duration(seconds: 3))] = 1;
-    sut.frames[spanStartTimestamp.add(Duration(seconds: 4))] = 1;
+    sut.exceededFrames[spanStartTimestamp.subtract(Duration(seconds: 5))] = 1;
+    sut.exceededFrames[spanStartTimestamp.subtract(Duration(seconds: 3))] = 1;
+    sut.exceededFrames[spanStartTimestamp.add(Duration(seconds: 4))] = 1;
 
     await sut.onSpanFinished(span1, spanEndTimestamp);
 
-    expect(sut.frames, hasLength(1));
-    expect(sut.frames.keys.first, spanStartTimestamp.add(Duration(seconds: 4)));
+    expect(sut.exceededFrames, hasLength(1));
+    expect(sut.exceededFrames.keys.first,
+        spanStartTimestamp.add(Duration(seconds: 4)));
   });
 
   test(
@@ -142,7 +142,7 @@ void main() {
     final now = DateTime.now();
     when(span.startTimestamp).thenReturn(now);
     when(span.endTimestamp).thenReturn(now.add(Duration(milliseconds: 500)));
-    sut.frames[now.add(Duration(milliseconds: 200))] = 100;
+    sut.exceededFrames[now.add(Duration(milliseconds: 200))] = 100;
 
     final metrics = sut.calculateFrameMetrics(span, span.endTimestamp!, 60);
 
@@ -160,7 +160,7 @@ void main() {
     final now = DateTime.now();
     when(span.startTimestamp).thenReturn(now);
     when(span.endTimestamp).thenReturn(now.add(Duration(milliseconds: 500)));
-    sut.frames[now.subtract(Duration(milliseconds: 200))] = 100;
+    sut.exceededFrames[now.subtract(Duration(milliseconds: 200))] = 100;
 
     final metrics = sut.calculateFrameMetrics(span, span.endTimestamp!, 60);
 
@@ -180,7 +180,7 @@ void main() {
     when(span.startTimestamp).thenReturn(now);
     when(span.endTimestamp).thenReturn(now.add(Duration(milliseconds: 500)));
     // 50ms before span starts and ends 50ms after span starts
-    sut.frames[now.add(Duration(milliseconds: 50))] = 100;
+    sut.exceededFrames[now.add(Duration(milliseconds: 50))] = 100;
 
     final metrics = sut.calculateFrameMetrics(span, span.endTimestamp!, 60);
 
@@ -199,7 +199,7 @@ void main() {
     final now = DateTime.now();
     when(span.startTimestamp).thenReturn(now);
     when(span.endTimestamp).thenReturn(now.add(Duration(milliseconds: 500)));
-    sut.frames[now.add(Duration(milliseconds: 550))] = 100;
+    sut.exceededFrames[now.add(Duration(milliseconds: 550))] = 100;
 
     final metrics = sut.calculateFrameMetrics(span, span.endTimestamp!, 60);
 
@@ -270,20 +270,20 @@ void main() {
 
     when(span.startTimestamp).thenReturn(DateTime.now());
     sut.activeSpans.add(span);
-    sut.frames[DateTime.now()] = 1;
+    sut.exceededFrames[DateTime.now()] = 1;
     const maxFramesToTrack = 1000;
     sut.maxFramesToTrack = maxFramesToTrack;
 
     for (var i = 1; i <= maxFramesToTrack; i++) {
       await Future<void>.delayed(
           Duration(milliseconds: 1)); // Add a small delay
       if (i == maxFramesToTrack - 1) {
-        expect(sut.frames.length, maxFramesToTrack - 1);
+        expect(sut.exceededFrames.length, maxFramesToTrack - 1);
       }
       await sut.measureFrameDuration(Duration.zero);
     }
 
-    expect(sut.frames, isEmpty);
+    expect(sut.exceededFrames, isEmpty);
     expect(sut.activeSpans, isEmpty);
     expect(sut.displayRefreshRate, isNull);
     expect(sut.isTrackingPaused, isTrue);
@@ -296,8 +296,12 @@ class Fixture {
   final fakeFrameCallbackHandler = FakeFrameCallbackHandler();
   final mockSentryNative = MockSentryNativeBinding();
 
-  SpanFrameMetricsCollector get sut => SpanFrameMetricsCollector(options,
-      frameCallbackHandler: fakeFrameCallbackHandler,
-      native: mockSentryNative,
-      isTestMode: true);
+  SpanFrameMetricsCollector get sut {
+    return SpanFrameMetricsCollector(options,
+        frameCallbackHandler: fakeFrameCallbackHandler,
+        native: mockSentryNative,
+        isTestMode: true)
+      ..displayRefreshRate = 60
+      ..expectedFrameDuration = Duration(milliseconds: 16);
+  }
 }