diff --git a/flutter/example/lib/auto_close_screen.dart b/flutter/example/lib/auto_close_screen.dart index 51fe4a809f..7caa09a836 100644 --- a/flutter/example/lib/auto_close_screen.dart +++ b/flutter/example/lib/auto_close_screen.dart @@ -27,7 +27,7 @@ class AutoCloseScreenState extends State { description: 'running a $delayInSeconds seconds operation'); await Future.delayed(const Duration(seconds: delayInSeconds)); await childSpan?.finish(); - SentryFlutter.reportFullDisplay(); + 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 index 0c584582a7..a347d87af9 100644 --- a/flutter/example/lib/main.dart +++ b/flutter/example/lib/main.dart @@ -103,7 +103,7 @@ class _MyAppState extends State { @override Widget build(BuildContext context) { - SentryFlutter.reportFullDisplay(); + // SentryFlutter.reportFullDisplay(); return feedback.BetterFeedback( child: ChangeNotifierProvider( create: (_) => ThemeProvider(), diff --git a/flutter/lib/src/event_processor/native_app_start_event_processor.dart b/flutter/lib/src/event_processor/native_app_start_event_processor.dart index db4bd96285..0a83ceab4b 100644 --- a/flutter/lib/src/event_processor/native_app_start_event_processor.dart +++ b/flutter/lib/src/event_processor/native_app_start_event_processor.dart @@ -2,6 +2,7 @@ import 'dart:async'; import 'package:sentry/sentry.dart'; +import '../integrations/integrations.dart'; import '../native/sentry_native.dart'; /// EventProcessor that enriches [SentryTransaction] objects with app start @@ -18,28 +19,9 @@ class NativeAppStartEventProcessor implements EventProcessor { @override Future apply(SentryEvent event, {Hint? hint}) async { - final appStartEnd = _native.appStartEnd; - - if (appStartEnd != null && - event is SentryTransaction && - !_native.didFetchAppStart) { - final nativeAppStart = await _native.fetchNativeAppStart(); - if (nativeAppStart == null) { - return event; - } - final measurement = nativeAppStart.toMeasurement(appStartEnd); - // We filter out app start more than 60s. - // This could be due to many different reasons. - // If you do the manual init and init the SDK too late and it does not - // compute the app start end in the very first Screen. - // If the process starts but the App isn't in the foreground. - // If the system forked the process earlier to accelerate the app start. - // And some unknown reasons that could not be reproduced. - // We've seen app starts with hours, days and even months. - if (measurement.value >= _maxAppStartMillis) { - return event; - } - + final appStartInfo = AppStartTracker().appStartInfo; + if (appStartInfo != null && event is SentryTransaction) { + final measurement = appStartInfo.measurement; event.measurements[measurement.name] = measurement; } return event; diff --git a/flutter/lib/src/integrations/native_app_start_integration.dart b/flutter/lib/src/integrations/native_app_start_integration.dart index fc95000d74..d767e7d28b 100644 --- a/flutter/lib/src/integrations/native_app_start_integration.dart +++ b/flutter/lib/src/integrations/native_app_start_integration.dart @@ -1,4 +1,5 @@ import 'package:flutter/scheduler.dart'; +import 'package:meta/meta.dart'; import 'package:sentry/sentry.dart'; import '../../sentry_flutter.dart'; @@ -23,18 +24,14 @@ class NativeAppStartIntegration extends Integration { 'Scheduler binding is null. Can\'t auto detect app start time.'); } else { schedulerBinding.addPostFrameCallback((timeStamp) async { + final appStartEnd = options.clock(); // ignore: invalid_use_of_internal_member - _native.appStartEnd = options.clock(); + _native.appStartEnd = appStartEnd; - final appStartEnd = _native.appStartEnd; + if (!_native.didFetchAppStart) { + final nativeAppStart = await _native.fetchNativeAppStart(); + final measurement = nativeAppStart?.toMeasurement(appStartEnd!); - if (_native.appStartEnd != null && !_native!.didFetchAppStart) { - print('fetch app start'); - final nativeAppStart = await _native!.fetchNativeAppStart(); - if (nativeAppStart == null) { - return; - } - final measurement = nativeAppStart.toMeasurement(appStartEnd!); // We filter out app start more than 60s. // This could be due to many different reasons. // If you do the manual init and init the SDK too late and it does not @@ -43,49 +40,23 @@ class NativeAppStartIntegration extends Integration { // If the system forked the process earlier to accelerate the app start. // And some unknown reasons that could not be reproduced. // We've seen app starts with hours, days and even months. - if (measurement.value >= 60000) { + if (nativeAppStart == null || + measurement == null || + measurement.value >= 60000) { + AppStartTracker().setAppStartInfo(null); return; } - final appStartDateTime = DateTime.fromMillisecondsSinceEpoch( - nativeAppStart.appStartTime.toInt()); - - final transactionContext2 = SentryTransactionContext( - 'root ("/")', - 'ui.load', - transactionNameSource: SentryTransactionNameSource.component, - // ignore: invalid_use_of_internal_member - origin: SentryTraceOrigins.autoNavigationRouteObserver, + final appStartInfo = AppStartInfo( + DateTime.fromMillisecondsSinceEpoch( + nativeAppStart.appStartTime.toInt()), + appStartEnd, + measurement, ); - final transaction2 = hub.startTransactionWithContext( - transactionContext2, - waitForChildren: true, - autoFinishAfter: Duration(seconds: 3), - trimEnd: true, - startTimestamp: appStartDateTime, - onFinish: (transaction) async { - final nativeFrames = await _native - ?.endNativeFramesCollection(transaction.context.traceId); - if (nativeFrames != null) { - final measurements = nativeFrames.toMeasurements(); - for (final item in measurements.entries) { - final measurement = item.value; - transaction.setMeasurement( - item.key, - measurement.value, - unit: measurement.unit, - ); - } - } - }); - - final ttidSpan = transaction2.startChild('ui.load.initial_display', startTimestamp: appStartDateTime); - await ttidSpan.finish(endTimestamp: appStartEnd); - - SentryNavigatorObserver.ttfdSpan = transaction2.startChild('ui.load.full_display', startTimestamp: appStartDateTime); - - print('end of the road'); + AppStartTracker().setAppStartInfo(appStartInfo); + } else { + AppStartTracker().setAppStartInfo(null); } }); } @@ -99,3 +70,40 @@ class NativeAppStartIntegration extends Integration { /// Used to provide scheduler binding at call time. typedef SchedulerBindingProvider = SchedulerBinding? Function(); + +@internal +class AppStartInfo { + final DateTime start; + final DateTime end; + final SentryMeasurement measurement; + + AppStartInfo(this.start, this.end, this.measurement); +} + +@internal +class AppStartTracker { + static final AppStartTracker _instance = AppStartTracker._internal(); + + factory AppStartTracker() => _instance; + + AppStartInfo? _appStartInfo; + + AppStartInfo? get appStartInfo => _appStartInfo; + Function(AppStartInfo?)? _callback; + + AppStartTracker._internal(); + + void setAppStartInfo(AppStartInfo? appStartInfo) { + _appStartInfo = appStartInfo; + _notifyObserver(); + } + + void onAppStartComplete(Function(AppStartInfo?) callback) { + _callback = callback; + _callback?.call(_appStartInfo); + } + + void _notifyObserver() { + _callback?.call(_appStartInfo); + } +} diff --git a/flutter/lib/src/navigation/sentry_navigator_observer.dart b/flutter/lib/src/navigation/sentry_navigator_observer.dart index b82a3b1f6e..749cc5d5dd 100644 --- a/flutter/lib/src/navigation/sentry_navigator_observer.dart +++ b/flutter/lib/src/navigation/sentry_navigator_observer.dart @@ -5,6 +5,7 @@ import 'package:meta/meta.dart'; import '../../sentry_flutter.dart'; import '../event_processor/flutter_enricher_event_processor.dart'; import '../event_processor/native_app_start_event_processor.dart'; +import '../integrations/integrations.dart'; import '../native/sentry_native.dart'; /// This key must be used so that the web interface displays the events nicely @@ -77,6 +78,11 @@ class SentryNavigatorObserver extends RouteObserver> { _native = SentryFlutter.native { if (enableAutoTransactions) { // ignore: invalid_use_of_internal_member + // _timingManager = NavigationTimingManager( + // hub: _hub, + // native: _native, + // autoFinishAfter: autoFinishAfter, + // ); _hub.options.sdk.addIntegration('UINavigationTracing'); } } @@ -88,10 +94,14 @@ class SentryNavigatorObserver extends RouteObserver> { final RouteNameExtractor? _routeNameExtractor; final AdditionalInfoExtractor? _additionalInfoProvider; final SentryNative? _native; + late final NavigationTimingManager? _timingManager; static ISentrySpan? _transaction2; static ISentrySpan? get transaction2 => _transaction2; + static final Map ttidSpanMap = {}; + static final Map ttfdSpanMap = {}; + ISentrySpan? _transaction; static String? _currentRouteName; @@ -119,6 +129,8 @@ class SentryNavigatorObserver extends RouteObserver> { _finishTransaction(); _startTransaction(route); + NavigationTimingManager2().startMeasurement(_getRouteName(route) ?? 'Unknown'); + final startTime = DateTime.now(); // Start timing DateTime? approximationEndTimestamp; @@ -132,26 +144,67 @@ class SentryNavigatorObserver extends RouteObserver> { startTime.millisecondsSinceEpoch; }); - SentryDisplayTracker().startTimeout(routeName ?? 'Unknown', () { - if (routeName == '/') { - // TODO: Does TTID have to be completely in line with app start? - // If yes, how do we access the appstart metrics - } else { - _transaction2?.setMeasurement( - 'time_to_initial_display', approximationDurationMillis!, - unit: DurationSentryMeasurementUnit.milliSecond); - ttidSpan?.finish(endTimestamp: approximationEndTimestamp!); - print('finished already'); - } - }); - } - - void freezeUIForSeconds(int seconds) { - var sw = Stopwatch()..start(); - while (sw.elapsed.inSeconds < seconds) { - // This loop will block the UI thread. + // Approximation started + // SentryDisplayTracker().startTimeout(routeName ?? 'Unknown', () { + // print('was ned') + // if (routeName == '/') { + // AppStartTracker().onAppStartComplete((appStartInfo) { + // final transactionContext2 = SentryTransactionContext( + // 'root ("/")', + // 'ui.load', + // transactionNameSource: SentryTransactionNameSource.component, + // // ignore: invalid_use_of_internal_member + // origin: SentryTraceOrigins.autoNavigationRouteObserver, + // ); + // final startTime = appStartInfo?.start ?? DateTime.now(); + // final endTime = appStartInfo?.end ?? approximationEndTimestamp!; + // final duration = + // appStartInfo?.end.difference(startTime).inMilliseconds ?? + // approximationDurationMillis!; + // _transaction2 = _hub.startTransactionWithContext( + // transactionContext2, + // waitForChildren: true, + // autoFinishAfter: _autoFinishAfter, + // trimEnd: true, + // startTimestamp: startTime, + // onFinish: (transaction) async { + // final nativeFrames = await _native + // ?.endNativeFramesCollection(transaction.context.traceId); + // if (nativeFrames != null) { + // final measurements = nativeFrames.toMeasurements(); + // for (final item in measurements.entries) { + // final measurement = item.value; + // transaction.setMeasurement( + // item.key, + // measurement.value, + // unit: measurement.unit, + // ); + // } + // } + // }, + // ); + // _transaction2?.setMeasurement('time_to_initial_display', duration, + // unit: DurationSentryMeasurementUnit.milliSecond); + // final ttidSpan = _transaction2?.startChild('ui.load.initial_display', + // description: 'root ("/")', startTimestamp: startTime); + // ttidSpan?.finish(endTimestamp: endTime); + // }); + // // Only finish ttidSpan if we get the appStartTime and appStartEnd + // } else { + // _transaction2?.setMeasurement( + // 'time_to_initial_display', approximationDurationMillis!, + // unit: DurationSentryMeasurementUnit.milliSecond); + // ttidSpanMap[routeName] + // ?.finish(endTimestamp: approximationEndTimestamp!); + // } + // }); + + try { + // ignore: invalid_use_of_internal_member + _hub.options.sdk.addIntegration('UINavigationTracing'); + } on Exception catch (e) { + print(e); } - sw.stop(); } @override @@ -236,13 +289,6 @@ class SentryNavigatorObserver extends RouteObserver> { if (name == '/') { name = 'root ("/")'; } - // final transactionContext = SentryTransactionContext( - // name, - // 'navigation', - // transactionNameSource: SentryTransactionNameSource.component, - // // ignore: invalid_use_of_internal_member - // origin: SentryTraceOrigins.autoNavigationRouteObserver, - // ); final transactionContext2 = SentryTransactionContext( name, @@ -252,9 +298,7 @@ class SentryNavigatorObserver extends RouteObserver> { origin: SentryTraceOrigins.autoNavigationRouteObserver, ); - if (name == 'root ("/")') { - - } else { + if (name != 'root ("/")') { _transaction2 = _hub.startTransactionWithContext( transactionContext2, waitForChildren: true, @@ -285,16 +329,13 @@ class SentryNavigatorObserver extends RouteObserver> { } if (name == 'root ("/")') { - // root ttid spans have to align with app start - // so the ttid instrumentation needs to be different here. - // startTime = DateTime.now(); - // ttidSpan = _transaction2?.startChild('ui.load.initial_display', description: '$name initial display', startTimestamp: startTime); - // ttidSpan?.origin = 'auto.ui.time_to_display'; } else { startTime = DateTime.now(); - ttidSpan = _transaction2?.startChild('ui.load.initial_display', + + final ttidSpan = _transaction2?.startChild('ui.load.initial_display', description: '$name initial display', startTimestamp: startTime); ttidSpan?.origin = 'auto.ui.time_to_display'; + ttidSpanMap[name] = ttidSpan!; } // TODO: Needs to finish max within 30 seconds @@ -306,6 +347,7 @@ class SentryNavigatorObserver extends RouteObserver> { // e.g the complex operation span in autoclosescreen if ((_hub.options as SentryFlutterOptions).enableTimeToFullDisplayTracing && name != 'root ("/")') { + print('ttfd'); ttfdStartTime = DateTime.now(); ttfdSpan = _transaction2?.startChild('ui.load.full_display', description: '$name full display', startTimestamp: ttfdStartTime); @@ -404,3 +446,250 @@ extension NativeFramesMeasurement on NativeFrames { }; } } + +class NavigationTimingManager { + late final Hub _hub; + late final SentryNative? _native; + late final Duration _autoFinishAfter; + ISentrySpan? _currentTransaction; + DateTime? _transactionStartTime; + + TTIDStrategy ttidStrategy = ApproximationTTIDStrategy(); + + static final NavigationTimingManager _instance = + NavigationTimingManager._internal(); + + factory NavigationTimingManager( + {required Hub hub, + SentryNative? native, + required Duration autoFinishAfter}) { + _instance._hub = hub; + _instance._native = native; + _instance._autoFinishAfter = autoFinishAfter; + return _instance; + } + + NavigationTimingManager._internal( + {Hub? hub, SentryNative? native, Duration? autoFinishAfter}) + : _hub = hub ?? HubAdapter(), + _native = native, + _autoFinishAfter = autoFinishAfter ?? Duration(seconds: 3); + + void startTransaction(String routeName, {bool isRootRoute = false}) { + final transactionContext = SentryTransactionContext( + routeName, + 'ui.load', + transactionNameSource: SentryTransactionNameSource.component, + origin: SentryTraceOrigins.autoNavigationRouteObserver, + ); + + _currentTransaction = _hub.startTransactionWithContext( + transactionContext, + waitForChildren: true, + autoFinishAfter: _autoFinishAfter, + trimEnd: true, + onFinish: _onTransactionFinish, + ); + + _transactionStartTime = DateTime.now(); + if (isRootRoute) { + _handleRootRouteTTID(); + } + } + + void finishTransaction() { + _currentTransaction?.status ??= SpanStatus.ok(); + _currentTransaction?.finish(endTimestamp: DateTime.now()); + } + + Future _onTransactionFinish(ISentrySpan transaction) async { + final nativeFrames = + await _native?.endNativeFramesCollection(transaction.context.traceId); + if (nativeFrames != null) { + final measurements = nativeFrames.toMeasurements(); + for (final item in measurements.entries) { + final measurement = item.value; + transaction.setMeasurement( + item.key, + measurement.value, + unit: measurement.unit, + ); + } + } + } + + void _handleRootRouteTTID() { + // Special handling for TTID measurement on the root route. + } +} + +@internal +class NavigationTimingManager2 { + static NavigationTimingManager2? _instance; + final Hub _hub; + final Duration _autoFinishAfter; + final SentryNative? _native; + + static final Map ttidSpanMap = {}; + static final Map ttfdSpanMap = {}; + + TTIDStrategy _strategy; + + NavigationTimingManager2._({ + Hub? hub, + Duration autoFinishAfter = const Duration(seconds: 3), + SentryNative? native, + }) : _hub = hub ?? HubAdapter(), + _autoFinishAfter = autoFinishAfter, + _native = native, + _strategy = ApproximationTTIDStrategy(); + + factory NavigationTimingManager2({ + Hub? hub, + Duration autoFinishAfter = const Duration(seconds: 3), + }) { + _instance ??= NavigationTimingManager2._( + hub: hub ?? HubAdapter(), + autoFinishAfter: autoFinishAfter, + native: SentryFlutter.native, + ); + + return _instance!; + } + + void startMeasurement(String routeName) { + SentryDisplayTracker().startTimeout(routeName ?? 'Unknown', () { + // If we got inside this block, it means manual instrumentation was not done + // handle non-root approximation ttid + // non-root approximation ttid only finishes the span here and needs to get + // the duration and end of the approximation which we got from addPostFrameCallback + // e.g ttidSpan.finish() + if (_strategy is ApproximationTTIDStrategy && routeName != '/') { + print('start measureing'); + _strategy.startMeasurement(routeName); + } + }); + + } + + void endMeasurement() { + final endTime = DateTime.now(); + _strategy.endMeasurement(endTime: endTime); + } + + void startTransaction(String routeName) { + final transactionContext = SentryTransactionContext( + routeName, + 'ui.load', + transactionNameSource: SentryTransactionNameSource.component, + origin: SentryTraceOrigins.autoNavigationRouteObserver, + ); + + final approximationStartTime = DateTime.now(); + SchedulerBinding.instance.addPostFrameCallback((timeStamp) { + final approximationEndTime = DateTime.now(); + // this marks the end of the approximation + }); + + if (isRootRoute(routeName)) { + handleRootTTID(); + } else { + handleNonRootTTID(transactionContext); + } + } + + void handleNonRootTTID(SentryTransactionContext transactionContext) { + _hub.startTransactionWithContext( + transactionContext, + waitForChildren: true, + autoFinishAfter: _autoFinishAfter, + trimEnd: true, + onFinish: _onTransactionFinish, + ); + } + + void handleRootTTID() {} + + bool isRootRoute(String routeName) { + return routeName == '/' || routeName == 'root ("/")'; + } + + Future _onTransactionFinish(ISentrySpan transaction) async { + final nativeFrames = + await _native?.endNativeFramesCollection(transaction.context.traceId); + if (nativeFrames != null) { + final measurements = nativeFrames.toMeasurements(); + for (final item in measurements.entries) { + final measurement = item.value; + transaction.setMeasurement( + item.key, + measurement.value, + unit: measurement.unit, + ); + } + } + } + + void handleTTIDStrategy(String routeName) { + // SentryDisplayTracker().startTimeout(routeName ?? 'Unknown', () { + // // If we got inside this block, it means manual instrumentation was not done + // // handle non-root approximation ttid + // // non-root approximation ttid only finishes the span here and needs to get + // // the duration and end of the approximation which we got from addPostFrameCallback + // // e.g ttidSpan.finish() + // _strategy.startMeasurement(routeName); + // }); + } + + // This is the manual approach + static void reportInitiallyDisplayed() {} + + static void reportFullyDisplayed() {} +} + +// Abstract strategy for TTID measurement +abstract class TTIDStrategy { + void startMeasurement(String routeName); + + void endMeasurement({required DateTime endTime, String? routeName}); +} + +// Implements approximation strategy for TTID +class ApproximationTTIDStrategy implements TTIDStrategy { + DateTime approximationStartTime = DateTime.now(); + DateTime approximationEndTime = DateTime.now(); + + @override + void startMeasurement(String routeName) { + approximationStartTime = DateTime.now(); + + final transaction = Sentry.getSpan(); + // SentryNavigatorObserver.ttidSpanMap[routeName] = + SchedulerBinding.instance.addPostFrameCallback((timeStamp) { + print('approximation end'); + endMeasurement(endTime: DateTime.now(), routeName: routeName); + }); + } + + @override + void endMeasurement({required DateTime endTime, String? routeName}) { + SentryNavigatorObserver.ttidSpanMap[routeName]?.finish( + endTimestamp: endTime, + ); + } +} + +// Implements manual strategy for TTID +class ManualTTIDStrategy implements TTIDStrategy { + @override + void startMeasurement(String routeName) { + print("Manual instrumentation started for $routeName"); + // Manual instrumentation logic + } + + @override + void endMeasurement({required DateTime endTime, String? routeName}) { + print("Manual instrumentation ended for $routeName at $endTime"); + // Calculate and log manual measurement + } +} diff --git a/flutter/lib/src/sentry_flutter.dart b/flutter/lib/src/sentry_flutter.dart index cb733efa06..f74dea74c0 100644 --- a/flutter/lib/src/sentry_flutter.dart +++ b/flutter/lib/src/sentry_flutter.dart @@ -233,27 +233,35 @@ mixin SentryFlutter { final routeName = ModalRoute.of(context)?.settings.name ?? 'Unknown'; final endTime = DateTime.now(); if (!SentryDisplayTracker().reportManual(routeName)) { - SentryNavigatorObserver.transaction2?.setMeasurement( - 'time_to_initial_display', - endTime.millisecondsSinceEpoch - SentryNavigatorObserver.startTime.millisecondsSinceEpoch, + final transaction = Sentry.getSpan(); + final duration = endTime.millisecondsSinceEpoch - + SentryNavigatorObserver.startTime.millisecondsSinceEpoch; + transaction?.setMeasurement('time_to_initial_display', duration, unit: DurationSentryMeasurementUnit.milliSecond); - SentryNavigatorObserver.ttidSpan?.finish(endTimestamp: endTime); + if (routeName == '/') { + print('is root screen manual'); + } else { + SentryNavigatorObserver.ttidSpanMap[routeName]?.finish( + endTimestamp: endTime, + ); + } } } /// Reports the time it took for the screen to be fully displayed. - static void reportFullDisplay() { + static void reportFullyDisplayed() { final endTime = DateTime.now(); - print('end of the road2'); SentryNavigatorObserver.ttfdSpan?.setMeasurement( 'time_to_full_display', - endTime.millisecondsSinceEpoch - SentryNavigatorObserver.ttfdStartTime.millisecondsSinceEpoch, + endTime.millisecondsSinceEpoch - + SentryNavigatorObserver.ttfdStartTime.millisecondsSinceEpoch, unit: DurationSentryMeasurementUnit.milliSecond); SentryNavigatorObserver.ttfdSpan?.finish(endTimestamp: endTime); } @internal static SentryNative? get native => _native; + @internal static set native(SentryNative? value) => _native = value; static SentryNative? _native; diff --git a/flutter/lib/src/sentry_widget.dart b/flutter/lib/src/sentry_widget.dart index 7db077a3e5..49381c9083 100644 --- a/flutter/lib/src/sentry_widget.dart +++ b/flutter/lib/src/sentry_widget.dart @@ -2,6 +2,7 @@ import 'dart:async'; import 'package:flutter/cupertino.dart'; import 'package:flutter/material.dart'; +import 'package:meta/meta.dart'; import '../sentry_flutter.dart'; /// This widget serves as a wrapper to include Sentry widgets such @@ -64,7 +65,7 @@ class SentryDisplayTracker { void startTimeout(String routeName, Function onTimeout) { _timers[routeName]?.cancel(); // Cancel any existing timer - _timers[routeName] = Timer(Duration(seconds: 2), () { + _timers[routeName] = Timer(Duration(seconds: 1), () { // Don't send if we already received a manual report or if we're on the root route e.g App start. if (!(_manualReportReceived[routeName] ?? false)) { onTimeout();