feat: ttfd (#1920)

* Change app start integration in a way that works with ttid as well * Formatting * Update * add visibleForTesting * Update * update * Add app start info test * Remove set app start info null * Review improvements * Add TTID * Improvements * Improvements * Fix integration test * Update * Clear after tracking * Update CHANGELOG * Format * Update * Update * remove import * Update sentry tracer * Add (not all) improvements for pr review * combine transaction handler * Refactor trackAppStart and trackRegularRoute to use private method * Fix dart analyzer * Remove clear * Clear in tearDown * Apply suggestions from code review Co-authored-by: Philipp Hofmann <philipp.hofmann@sentry.io> * Apply PR suggestions * fix analyze * update * update * Fix tests * Fix analyze * revert sample * Update * Update * Fix child timestamp trimming * Update CHANGELOG * Run formatting * Update docs * Revert * Fix test * Move clear to the beginning of function * initial commit * Fix start time * Fix analyze * remove comment * Formatting * update * fix test * Add changelog * Update * Update * fix analyze * fix tests * formatting * add ttid duration assertion and determineEndTime timeout * Rename finish transaction and do an early exit with enableAutoTransactions * Rename function * Remove static and getter for in navigator observer * Expose SentryDisplayWidget as public api and add it to example app * Fix dart analyze * Fix dart doc * Get display tracker as static for reportFullyDisplayed() * Add @internal * Fix test * Improve tests * Reduce fake frame finishing time and improve tests * Improve test names * Fix tests * Apply formatting * Add extra assertion in tests * Improve * Use utc date time * Fix test * Fix dartdoc * Update test * Update test * Fix tests * Fix changelog * Update * Improve * Update * Improve tests * Update * Change function to private * Update CHANGELOG.md * Rename function * add improvements (not all) * Fix tests * Update changelog * Finish after setting scope span to null * update * updaet * update * clear first in didPush * update * update example * add improvements --------- Co-authored-by: Philipp Hofmann <philipp.hofmann@sentry.io>
getsentry · Mar 13, 2024 · d089990 · d089990
1 parent e8603bb
commit d089990
Show file tree

Hide file tree

Showing 16 changed files with 886 additions and 125 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -1,9 +1,24 @@
 # Changelog
 
 ## Unreleased
-
+    
 ## Features
 
+- Add TTFD (time to full display), which allows you to measure the time it takes to render the full screen ([#1920](https://github.com/getsentry/sentry-dart/pull/1920))
+  - Requires using the [routing instrumentation](https://docs.sentry.io/platforms/flutter/integrations/routing-instrumentation/).
+  - Set `enableTimeToFullDisplayTracing = true` in your `SentryFlutterOptions` to enable TTFD
+  - Manually report the end of the full display by calling `SentryFlutter.reportFullyDisplayed()`
+  - If not reported within 30 seconds, the span will be automatically finish with the status `deadline_exceeded`
+- Add TTID (time to initial display), which allows you to measure the time it takes to render the first frame of your screen ([#1910](https://github.com/getsentry/sentry-dart/pull/1910))
+  - Requires using the [routing instrumentation](https://docs.sentry.io/platforms/flutter/integrations/routing-instrumentation/).
+  - Introduces two modes:
+    - `automatic` mode is enabled by default for all screens and will yield only an approximation result.
+    - `manual` mode requires manual instrumentation and will yield a more accurate result.
+      - To use `manual` mode, you need to wrap your desired widget: `SentryDisplayWidget(child: MyScreen())`.
+    - You can mix and match both modes in your app.
+  - Other significant fixes
+    - `didPop` doesn't trigger a new transaction
+    - Change transaction operation name to `ui.load` instead of `navigation`
 - Add override `captureFailedRequests` option ([#1931](https://github.com/getsentry/sentry-dart/pull/1931))
   - The `dio` integration and `SentryHttpClient` now take an additional `captureFailedRequests` option.
   - This is useful if you want to disable this option on native and only enable it on `dio` for example.
@@ -23,17 +38,7 @@
 - remove transitive dart:io reference for web ([#1898](https://github.com/getsentry/sentry-dart/pull/1898))  
 
 ### Features
-
-- Add TTID (time to initial display), which allows you to measure the time it takes to render the first frame of your screen ([#1910](https://github.com/getsentry/sentry-dart/pull/1910))
-  - Requires using the [routing instrumentation](https://docs.sentry.io/platforms/flutter/integrations/routing-instrumentation/).
-  - Introduces two modes: 
-    - `automatic` mode is enabled by default for all screens and will yield only an approximation result.
-    - `manual` mode requires manual instrumentation and will yield a more accurate result.
-      - To use `manual` mode, you need to wrap your desired widget: `SentryDisplayWidget(child: MyScreen())`.
-    - You can mix and match both modes in your app.
-  - Other significant fixes
-    - `didPop` doesn't trigger a new transaction
-    - Change transaction operation name to `ui.load` instead of `navigation`
+- 
 - Use `recordHttpBreadcrumbs` to set iOS `enableNetworkBreadcrumbs` ([#1884](https://github.com/getsentry/sentry-dart/pull/1884))
 - Apply `beforeBreadcrumb` on native iOS crumbs ([#1914](https://github.com/getsentry/sentry-dart/pull/1914))
 - Add `maxQueueSize` to limit the number of unawaited events sent to Sentry ([#1868](https://github.com/getsentry/sentry-dart/pull/1868))

diff --git a/dart/lib/src/sentry_measurement.dart b/dart/lib/src/sentry_measurement.dart
@@ -46,6 +46,13 @@ class SentryMeasurement {
         value = duration.inMilliseconds,
         unit = DurationSentryMeasurementUnit.milliSecond;
 
+  /// Duration of the time to full display in milliseconds
+  SentryMeasurement.timeToFullDisplay(Duration duration)
+      : assert(!duration.isNegative),
+        name = 'time_to_full_display',
+        value = duration.inMilliseconds,
+        unit = DurationSentryMeasurementUnit.milliSecond;
+
   final String name;
   final num value;
   final SentryMeasurementUnit? unit;

diff --git a/dart/lib/src/sentry_span_operations.dart b/dart/lib/src/sentry_span_operations.dart
@@ -4,4 +4,5 @@ import 'package:meta/meta.dart';
 class SentrySpanOperations {
   static const String uiLoad = 'ui.load';
   static const String uiTimeToInitialDisplay = 'ui.load.initial_display';
+  static const String uiTimeToFullDisplay = 'ui.load.full_display';
 }
diff --git a/dart/test/sentry_tracer_test.dart b/dart/test/sentry_tracer_test.dart
@@ -389,6 +389,7 @@ void main() {
     test('end trimmed to latest child end timestamp', () async {
       final sut = fixture.getSut(trimEnd: true);
       final rootEndInitial = getUtcDateTime();
+
       final childAEnd = rootEndInitial;
       final childBEnd = rootEndInitial.add(Duration(seconds: 1));
       final childCEnd = rootEndInitial;

diff --git a/flutter/example/lib/auto_close_screen.dart b/flutter/example/lib/auto_close_screen.dart
@@ -1,5 +1,9 @@
+import 'package:dio/dio.dart';
 import 'package:flutter/material.dart';
-import 'package:sentry/sentry.dart';
+import 'package:sentry_dio/sentry_dio.dart';
+import 'package:sentry_flutter/sentry_flutter.dart';
+
+import 'main.dart';
 
 /// This screen is only used to demonstrate how route navigation works.
 /// Init will create a child span and pop the screen after 3 seconds.
@@ -21,11 +25,14 @@ class AutoCloseScreenState extends State<AutoCloseScreen> {
   }
 
   Future<void> _doComplexOperationThenClose() async {
-    final activeSpan = Sentry.getSpan();
-    final childSpan = activeSpan?.startChild('complex operation',
-        description: 'running a $delayInSeconds seconds operation');
-    await Future.delayed(const Duration(seconds: delayInSeconds));
-    childSpan?.finish();
+    final dio = Dio();
+    dio.addSentry();
+    try {
+      await dio.get<String>(exampleUrl);
+    } catch (exception, stackTrace) {
+      await Sentry.captureException(exception, stackTrace: stackTrace);
+    }
+    SentryFlutter.reportFullyDisplayed();
     // ignore: use_build_context_synchronously
     Navigator.of(context).pop();
   }

diff --git a/flutter/example/lib/main.dart b/flutter/example/lib/main.dart
@@ -82,6 +82,7 @@ Future<void> setupSentry(
       // configuration issues, e.g. finding out why your events are not uploaded.
       options.debug = true;
       options.spotlight = Spotlight(enabled: true);
+      options.enableTimeToFullDisplayTracing = true;
 
       options.maxRequestBodySize = MaxRequestBodySize.always;
       options.maxResponseBodySize = MaxResponseBodySize.always;

diff --git a/flutter/lib/src/navigation/sentry_navigator_observer.dart b/flutter/lib/src/navigation/sentry_navigator_observer.dart
@@ -12,6 +12,9 @@ import '../../sentry_flutter.dart';
 import '../event_processor/flutter_enricher_event_processor.dart';
 import '../native/sentry_native.dart';
 
+// ignore: implementation_imports
+import 'package:sentry/src/sentry_tracer.dart';
+
 /// This key must be used so that the web interface displays the events nicely
 /// See https://develop.sentry.dev/sdk/event-payloads/breadcrumbs/
 const _navigationKey = 'navigation';
@@ -82,11 +85,23 @@ class SentryNavigatorObserver extends RouteObserver<PageRoute<dynamic>> {
         _setRouteNameAsTransaction = setRouteNameAsTransaction,
         _routeNameExtractor = routeNameExtractor,
         _additionalInfoProvider = additionalInfoProvider,
-        _native = SentryFlutter.native,
-        _timeToDisplayTracker = timeToDisplayTracker ?? TimeToDisplayTracker() {
+        _native = SentryFlutter.native {
     if (enableAutoTransactions) {
       _hub.options.sdk.addIntegration('UINavigationTracing');
     }
+    _timeToDisplayTracker =
+        timeToDisplayTracker ?? _initializeTimeToDisplayTracker();
+  }
+
+  /// Initializes the TimeToDisplayTracker with the option to enable time to full display tracing.
+  TimeToDisplayTracker _initializeTimeToDisplayTracker() {
+    bool enableTimeToFullDisplayTracing = false;
+    final options = _hub.options;
+    if (options is SentryFlutterOptions) {
+      enableTimeToFullDisplayTracing = options.enableTimeToFullDisplayTracing;
+    }
+    return TimeToDisplayTracker(
+        enableTimeToFullDisplayTracing: enableTimeToFullDisplayTracing);
   }
 
   final Hub _hub;
@@ -96,7 +111,11 @@ class SentryNavigatorObserver extends RouteObserver<PageRoute<dynamic>> {
   final RouteNameExtractor? _routeNameExtractor;
   final AdditionalInfoExtractor? _additionalInfoProvider;
   final SentryNative? _native;
-  final TimeToDisplayTracker? _timeToDisplayTracker;
+  static TimeToDisplayTracker? _timeToDisplayTracker;
+
+  @internal
+  static TimeToDisplayTracker? get timeToDisplayTracker =>
+      _timeToDisplayTracker;
 
   ISentrySpan? _transaction;
 
@@ -105,7 +124,7 @@ class SentryNavigatorObserver extends RouteObserver<PageRoute<dynamic>> {
   @internal
   static String? get currentRouteName => _currentRouteName;
 
-  Completer<void>? _completedDisplayTracking;
+  Completer<void>? _completedDisplayTracking = Completer();
 
   // Since didPush does not have a future, we can keep track of when the display tracking has finished
   @visibleForTesting
@@ -124,6 +143,8 @@ class SentryNavigatorObserver extends RouteObserver<PageRoute<dynamic>> {
       to: route.settings,
     );
 
+    // Clearing the display tracker here is safe since didPush happens before the Widget is built
+    _timeToDisplayTracker?.clear();
     _finishTimeToDisplayTracking();
     _startTimeToDisplayTracking(route);
   }
@@ -155,7 +176,7 @@ class SentryNavigatorObserver extends RouteObserver<PageRoute<dynamic>> {
       to: previousRoute?.settings,
     );
 
-    _finishTimeToDisplayTracking();
+    _finishTimeToDisplayTracking(clearAfter: true);
   }
 
   void _addBreadcrumb({
@@ -253,56 +274,96 @@ class SentryNavigatorObserver extends RouteObserver<PageRoute<dynamic>> {
     await _native?.beginNativeFramesCollection();
   }
 
-  Future<void> _finishTimeToDisplayTracking() async {
-    _timeToDisplayTracker?.clear();
-
+  Future<void> _finishTimeToDisplayTracking({bool clearAfter = false}) async {
     final transaction = _transaction;
     _transaction = null;
-    if (transaction == null || transaction.finished) {
-      return;
+    try {
+      _hub.configureScope((scope) {
+        if (scope.span == transaction) {
+          scope.span = null;
+        }
+      });
+
+      if (transaction == null || transaction.finished) {
+        return;
+      }
+
+      // Cancel unfinished TTID/TTFD spans, e.g this might happen if the user navigates
+      // away from the current route before TTFD or TTID is finished.
+      for (final child in (transaction as SentryTracer).children) {
+        final isTTIDSpan = child.context.operation ==
+            SentrySpanOperations.uiTimeToInitialDisplay;
+        final isTTFDSpan =
+            child.context.operation == SentrySpanOperations.uiTimeToFullDisplay;
+        if (!child.finished && (isTTIDSpan || isTTFDSpan)) {
+          await child.finish(status: SpanStatus.deadlineExceeded());
+        }
+      }
+    } catch (exception, stacktrace) {
+      _hub.options.logger(
+        SentryLevel.error,
+        'Error while finishing time to display tracking',
+        exception: exception,
+        stackTrace: stacktrace,
+      );
+    } finally {
+      await transaction?.finish();
+      if (clearAfter) {
+        _clear();
+      }
     }
-    transaction.status ??= SpanStatus.ok();
-    await transaction.finish();
   }
 
   Future<void> _startTimeToDisplayTracking(Route<dynamic>? route) async {
-    if (!_enableAutoTransactions) {
-      return;
-    }
+    try {
+      final routeName = _getRouteName(route) ?? _currentRouteName;
+      if (!_enableAutoTransactions || routeName == null) {
+        return;
+      }
 
-    _completedDisplayTracking = Completer<void>();
-    String? routeName = _currentRouteName;
-    if (routeName == null) return;
+      bool isAppStart = routeName == '/';
+      DateTime startTimestamp = _hub.options.clock();
+      DateTime? endTimestamp;
 
-    DateTime startTimestamp = _hub.options.clock();
-    DateTime? endTimestamp;
+      if (isAppStart) {
+        final appStartInfo = await NativeAppStartIntegration.getAppStartInfo();
+        if (appStartInfo == null) return;
 
-    if (routeName == '/') {
-      final appStartInfo = await NativeAppStartIntegration.getAppStartInfo();
-      if (appStartInfo == null) {
-        return;
+        startTimestamp = appStartInfo.start;
+        endTimestamp = appStartInfo.end;
       }
 
-      startTimestamp = appStartInfo.start;
-      endTimestamp = appStartInfo.end;
-    }
+      await _startTransaction(route, startTimestamp);
 
-    await _startTransaction(route, startTimestamp);
-    final transaction = _transaction;
-    if (transaction == null) {
-      return;
-    }
+      final transaction = _transaction;
+      if (transaction == null) {
+        return;
+      }
 
-    if (routeName == '/' && endTimestamp != null) {
-      await _timeToDisplayTracker?.trackAppStartTTD(transaction,
-          startTimestamp: startTimestamp, endTimestamp: endTimestamp);
-    } else {
-      await _timeToDisplayTracker?.trackRegularRouteTTD(transaction,
-          startTimestamp: startTimestamp);
+      if (isAppStart && endTimestamp != null) {
+        await _timeToDisplayTracker?.trackAppStartTTD(transaction,
+            startTimestamp: startTimestamp, endTimestamp: endTimestamp);
+      } else {
+        await _timeToDisplayTracker?.trackRegularRouteTTD(transaction,
+            startTimestamp: startTimestamp);
+      }
+    } catch (exception, stacktrace) {
+      _hub.options.logger(
+        SentryLevel.error,
+        'Error while tracking time to display',
+        exception: exception,
+        stackTrace: stacktrace,
+      );
+    } finally {
+      _clear();
     }
+  }
 
-    // Mark the tracking as completed and clear any temporary state.
-    _completedDisplayTracking?.complete();
+  void _clear() {
+    if (_completedDisplayTracking?.isCompleted == false) {
+      _completedDisplayTracking?.complete();
+    }
+    _completedDisplayTracking = Completer();
     _timeToDisplayTracker?.clear();
   }
 }

diff --git a/flutter/lib/src/navigation/time_to_display_tracker.dart b/flutter/lib/src/navigation/time_to_display_tracker.dart
@@ -1,34 +1,55 @@
 // ignore_for_file: invalid_use_of_internal_member
 
-import 'dart:async';
-
 import 'package:meta/meta.dart';
 
 import '../../sentry_flutter.dart';
+import 'time_to_full_display_tracker.dart';
 import 'time_to_initial_display_tracker.dart';
 
 @internal
 class TimeToDisplayTracker {
   final TimeToInitialDisplayTracker _ttidTracker;
+  final TimeToFullDisplayTracker? _ttfdTracker;
+  final bool enableTimeToFullDisplayTracing;
 
   TimeToDisplayTracker({
     TimeToInitialDisplayTracker? ttidTracker,
-  }) : _ttidTracker = ttidTracker ?? TimeToInitialDisplayTracker();
+    TimeToFullDisplayTracker? ttfdTracker,
+    required this.enableTimeToFullDisplayTracing,
+  })  : _ttidTracker = ttidTracker ?? TimeToInitialDisplayTracker(),
+        _ttfdTracker = enableTimeToFullDisplayTracing
+            ? ttfdTracker ?? TimeToFullDisplayTracker()
+            : null;
 
   Future<void> trackAppStartTTD(ISentrySpan transaction,
       {required DateTime startTimestamp,
       required DateTime endTimestamp}) async {
     // We start and immediately finish the spans since we cannot mutate the history of spans.
     await _ttidTracker.trackAppStart(transaction,
         startTimestamp: startTimestamp, endTimestamp: endTimestamp);
+    await _trackTTFDIfEnabled(transaction, startTimestamp);
   }
 
   Future<void> trackRegularRouteTTD(ISentrySpan transaction,
       {required DateTime startTimestamp}) async {
     await _ttidTracker.trackRegularRoute(transaction, startTimestamp);
+    await _trackTTFDIfEnabled(transaction, startTimestamp);
+  }
+
+  Future<void> _trackTTFDIfEnabled(
+      ISentrySpan transaction, DateTime startTimestamp) async {
+    if (enableTimeToFullDisplayTracing) {
+      await _ttfdTracker?.track(transaction, startTimestamp);
+    }
+  }
+
+  @internal
+  Future<void> reportFullyDisplayed() async {
+    return _ttfdTracker?.reportFullyDisplayed();
   }
 
   void clear() {
     _ttidTracker.clear();
+    _ttfdTracker?.clear();
   }
 }