Fix TTID timing issue (#2326)

* await finish before starting new ttid tracking * Fix issue where TTD was not recording every transacion * add cl entry * use correct timestamps, use teimestamp internally to handle completion before start * update tests
getsentry · Oct 4, 2024 · 905bf99 · 905bf99
1 parent 4bcf446
commit 905bf99
Show file tree

Hide file tree

Showing 5 changed files with 80 additions and 19 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -20,6 +20,7 @@
 - Only start frame tracking if we receive valid display refresh data ([#2307](https://github.com/getsentry/sentry-dart/pull/2307))
 - Rounding error used on frames.total and reject frame measurements if frames.total is less than frames.slow or frames.frozen ([#2308](https://github.com/getsentry/sentry-dart/pull/2308))
 - iOS replay integration when only `onErrorSampleRate` is specified ([#2306](https://github.com/getsentry/sentry-dart/pull/2306))
+- Fix TTID timing issue ([#2326](https://github.com/getsentry/sentry-dart/pull/2326))
 
 ### Deprecate
 

diff --git a/flutter/lib/src/navigation/sentry_navigator_observer.dart b/flutter/lib/src/navigation/sentry_navigator_observer.dart
@@ -159,8 +159,10 @@ class SentryNavigatorObserver extends RouteObserver<PageRoute<dynamic>> {
 
     // Clearing the display tracker here is safe since didPush happens before the Widget is built
     _timeToDisplayTracker?.clear();
-    _finishTimeToDisplayTracking();
-    _startTimeToDisplayTracking(route);
+
+    DateTime timestamp = _hub.options.clock();
+    _finishTimeToDisplayTracking(endTimestamp: timestamp);
+    _startTimeToDisplayTracking(route, timestamp);
   }
 
   @override
@@ -200,7 +202,8 @@ class SentryNavigatorObserver extends RouteObserver<PageRoute<dynamic>> {
       to: previousRoute?.settings,
     );
 
-    _finishTimeToDisplayTracking(clearAfter: true);
+    final timestamp = _hub.options.clock();
+    _finishTimeToDisplayTracking(endTimestamp: timestamp, clearAfter: true);
   }
 
   void _addBreadcrumb({
@@ -295,7 +298,8 @@ class SentryNavigatorObserver extends RouteObserver<PageRoute<dynamic>> {
     await _native?.beginNativeFrames();
   }
 
-  Future<void> _finishTimeToDisplayTracking({bool clearAfter = false}) async {
+  Future<void> _finishTimeToDisplayTracking(
+      {required DateTime endTimestamp, bool clearAfter = false}) async {
     final transaction = _transaction;
     _transaction = null;
     try {
@@ -317,7 +321,10 @@ class SentryNavigatorObserver extends RouteObserver<PageRoute<dynamic>> {
         final isTTFDSpan =
             child.context.operation == SentrySpanOperations.uiTimeToFullDisplay;
         if (!child.finished && (isTTIDSpan || isTTFDSpan)) {
-          await child.finish(status: SpanStatus.deadlineExceeded());
+          await child.finish(
+            endTimestamp: endTimestamp,
+            status: SpanStatus.deadlineExceeded(),
+          );
         }
       }
     } catch (exception, stacktrace) {
@@ -331,23 +338,22 @@ class SentryNavigatorObserver extends RouteObserver<PageRoute<dynamic>> {
         rethrow;
       }
     } finally {
-      await transaction?.finish();
+      await transaction?.finish(endTimestamp: endTimestamp);
       if (clearAfter) {
         _clear();
       }
     }
   }
 
-  Future<void> _startTimeToDisplayTracking(Route<dynamic>? route) async {
+  Future<void> _startTimeToDisplayTracking(
+      Route<dynamic>? route, DateTime startTimestamp) async {
     try {
       final routeName = _getRouteName(route) ?? _currentRouteName;
       if (!_enableAutoTransactions || routeName == null) {
         return;
       }
 
       bool isAppStart = routeName == '/';
-      DateTime startTimestamp = _hub.options.clock();
-
       await _startTransaction(route, startTimestamp);
 
       final transaction = _transaction;

diff --git a/flutter/lib/src/navigation/time_to_initial_display_tracker.dart b/flutter/lib/src/navigation/time_to_initial_display_tracker.dart
@@ -29,6 +29,8 @@ class TimeToInitialDisplayTracker {
   bool _isManual = false;
   Completer<DateTime?>? _trackingCompleter;
   DateTime? _endTimestamp;
+  DateTime? _completeTrackingTimeStamp;
+
   final Duration _determineEndtimeTimeout = Duration(seconds: 5);
 
   /// This endTimestamp is needed in the [TimeToFullDisplayTracker] class
@@ -87,6 +89,13 @@ class TimeToInitialDisplayTracker {
 
     // If we already know it's manual we can return the future immediately
     if (_isManual) {
+      final completeTrackingTimeStamp = _completeTrackingTimeStamp;
+      if (completeTrackingTimeStamp != null) {
+        // If complete was called before we could call start, complete it here.
+        _endTimestamp = completeTrackingTimeStamp;
+        _trackingCompleter?.complete(completeTrackingTimeStamp);
+        _completeTrackingTimeStamp = null;
+      }
       return future;
     }
 
@@ -106,10 +115,13 @@ class TimeToInitialDisplayTracker {
   }
 
   void completeTracking() {
+    final timestamp = DateTime.now();
+
     if (_trackingCompleter != null && !_trackingCompleter!.isCompleted) {
-      final endTimestamp = DateTime.now();
-      _endTimestamp = endTimestamp;
-      _trackingCompleter?.complete(endTimestamp);
+      _endTimestamp = timestamp;
+      _trackingCompleter?.complete(timestamp);
+    } else {
+      _completeTrackingTimeStamp = timestamp;
     }
   }
 

diff --git a/flutter/test/navigation/time_to_initial_display_tracker_test.dart b/flutter/test/navigation/time_to_initial_display_tracker_test.dart
@@ -84,6 +84,37 @@ void main() {
               .difference(ttidSpan.startTimestamp)
               .inMilliseconds);
     });
+
+    test('starting after completing still finished correctly', () async {
+      await Future.delayed(fixture.finishFrameDuration, () {
+        sut.markAsManual();
+        sut.completeTracking();
+      });
+
+      final transaction = fixture.getTransaction() as SentryTracer;
+      await sut.trackRegularRoute(transaction, fixture.startTimestamp);
+
+      final children = transaction.children;
+      expect(children, hasLength(1));
+
+      final ttidSpan = children.first;
+      expect(ttidSpan.context.operation,
+          SentrySpanOperations.uiTimeToInitialDisplay);
+      expect(ttidSpan.finished, isTrue);
+      expect(ttidSpan.context.description, 'Regular route initial display');
+      expect(ttidSpan.origin, SentryTraceOrigins.manualUiTimeToDisplay);
+      final ttidMeasurement =
+          transaction.measurements['time_to_initial_display'];
+      expect(ttidMeasurement, isNotNull);
+      expect(ttidMeasurement?.unit, DurationSentryMeasurementUnit.milliSecond);
+      expect(ttidMeasurement?.value,
+          greaterThanOrEqualTo(fixture.finishFrameDuration.inMilliseconds));
+      expect(
+          ttidMeasurement?.value,
+          ttidSpan.endTimestamp!
+              .difference(ttidSpan.startTimestamp)
+              .inMilliseconds);
+    });
   });
 
   group('determineEndtime', () {

diff --git a/flutter/test/sentry_navigator_observer_test.dart b/flutter/test/sentry_navigator_observer_test.dart
@@ -317,7 +317,8 @@ void main() {
         expect(scope.span, null);
       });
 
-      verify(span.finish()).called(2);
+      verify(span.finish(endTimestamp: captureAnyNamed('endTimestamp')))
+          .called(2);
     });
 
     test('didPop finishes transaction', () async {
@@ -344,7 +345,8 @@ void main() {
         expect(scope.span, null);
       });
 
-      verify(span.finish()).called(1);
+      verify(span.finish(endTimestamp: captureAnyNamed('endTimestamp')))
+          .called(1);
     });
 
     test('multiple didPop only finish transaction once', () async {
@@ -373,7 +375,8 @@ void main() {
         expect(scope.span, null);
       });
 
-      verify(span.finish()).called(1);
+      verify(span.finish(endTimestamp: captureAnyNamed('endTimestamp')))
+          .called(1);
     });
 
     test(
@@ -413,9 +416,13 @@ void main() {
 
       await Future<void>.delayed(const Duration(milliseconds: 100));
 
-      verify(mockChildA.finish(status: SpanStatus.deadlineExceeded()))
+      verify(mockChildA.finish(
+              endTimestamp: captureAnyNamed('endTimestamp'),
+              status: SpanStatus.deadlineExceeded()))
           .called(1);
-      verify(mockChildB.finish(status: SpanStatus.deadlineExceeded()))
+      verify(mockChildB.finish(
+              endTimestamp: captureAnyNamed('endTimestamp'),
+              status: SpanStatus.deadlineExceeded()))
           .called(1);
     });
 
@@ -456,9 +463,13 @@ void main() {
 
       await Future<void>.delayed(const Duration(milliseconds: 100));
 
-      verify(mockChildA.finish(status: SpanStatus.deadlineExceeded()))
+      verify(mockChildA.finish(
+              endTimestamp: captureAnyNamed('endTimestamp'),
+              status: SpanStatus.deadlineExceeded()))
           .called(1);
-      verify(mockChildB.finish(status: SpanStatus.deadlineExceeded()))
+      verify(mockChildB.finish(
+              endTimestamp: captureAnyNamed('endTimestamp'),
+              status: SpanStatus.deadlineExceeded()))
           .called(1);
     });