From 0ff29489638734979588593b5c13167b679e9232 Mon Sep 17 00:00:00 2001 From: Denis Andrasec Date: Mon, 7 Oct 2024 16:44:58 +0200 Subject: [PATCH 1/7] Handle TTFD for root screen transaction --- .../native_app_start_handler.dart | 56 +++--- .../native_app_start_integration.dart | 18 +- .../navigation/sentry_navigator_observer.dart | 11 +- .../navigation/time_to_display_tracker.dart | 50 +++--- .../time_to_full_display_tracker.dart | 57 ++++--- .../time_to_initial_display_tracker.dart | 24 ++- flutter/lib/src/sentry_flutter_options.dart | 6 + .../native_app_start_handler_test.dart | 103 ++++++----- .../time_to_display_tracker_test.dart | 160 ++++++++---------- .../time_to_full_display_tracker_test.dart | 10 +- .../time_to_initial_display_tracker_test.dart | 55 +++++- .../test/sentry_navigator_observer_test.dart | 2 +- 12 files changed, 295 insertions(+), 257 deletions(-) diff --git a/flutter/lib/src/integrations/native_app_start_handler.dart b/flutter/lib/src/integrations/native_app_start_handler.dart index a503d351d4..ae2a546361 100644 --- a/flutter/lib/src/integrations/native_app_start_handler.dart +++ b/flutter/lib/src/integrations/native_app_start_handler.dart @@ -21,7 +21,7 @@ class NativeAppStartHandler { static const _maxAppStartMillis = 60000; Future call(Hub hub, SentryFlutterOptions options, - {required DateTime? appStartEnd}) async { + {required DateTime appStartEnd}) async { _hub = hub; _options = options; @@ -42,11 +42,11 @@ class NativeAppStartHandler { SentrySpanOperations.uiLoad, startTimestamp: appStartInfo.start, ); - final ttidSpan = transaction.startChild( - SentrySpanOperations.uiTimeToInitialDisplay, - description: '$screenName initial display', - startTimestamp: appStartInfo.start, - ); + + await options.timeToDisplayTracker.track(transaction, + startTimestamp: appStartInfo.start, + endTimestamp: appStartInfo.end, + origin: SentryTraceOrigins.autoUiTimeToDisplay); // Enrich Transaction @@ -57,28 +57,19 @@ class NativeAppStartHandler { return; } - SentryMeasurement? measurement; - if (options.autoAppStart) { - measurement = appStartInfo.toMeasurement(); - } else if (appStartEnd != null) { - appStartInfo.end = appStartEnd; - measurement = appStartInfo.toMeasurement(); - } - + SentryMeasurement? measurement = appStartInfo.toMeasurement(); if (measurement != null) { sentryTracer.measurements[measurement.name] = measurement; await _attachAppStartSpans(appStartInfo, sentryTracer); } - // Finish Transaction & Span - - await ttidSpan.finish(endTimestamp: appStartInfo.end); + // Finish Transaction await transaction.finish(endTimestamp: appStartInfo.end); } _AppStartInfo? _infoNativeAppStart( NativeAppStart nativeAppStart, - DateTime? appStartEnd, + DateTime appStartEnd, ) { final sentrySetupStartDateTime = SentryFlutter.sentrySetupStartTime; if (sentrySetupStartDateTime == null) { @@ -90,23 +81,18 @@ class NativeAppStartHandler { final pluginRegistrationDateTime = DateTime.fromMillisecondsSinceEpoch( nativeAppStart.pluginRegistrationTime); - if (_options.autoAppStart) { - // We only assign the current time if it's not already set - this is useful in tests - appStartEnd ??= _options.clock(); - - final duration = appStartEnd.difference(appStartDateTime); - - // 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 (duration.inMilliseconds > _maxAppStartMillis) { - return null; - } + final duration = appStartEnd.difference(appStartDateTime); + + // 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 (duration.inMilliseconds > _maxAppStartMillis) { + return null; } List<_TimeSpan> nativeSpanTimes = []; diff --git a/flutter/lib/src/integrations/native_app_start_integration.dart b/flutter/lib/src/integrations/native_app_start_integration.dart index 31dc2b6ad8..77a4139881 100644 --- a/flutter/lib/src/integrations/native_app_start_integration.dart +++ b/flutter/lib/src/integrations/native_app_start_integration.dart @@ -34,14 +34,18 @@ class NativeAppStartIntegration extends Integration { _frameCallbackHandler.addPostFrameCallback((timeStamp) async { try { if (!options.autoAppStart && _appStartEnd == null) { - await _appStartEndCompleter.future - .timeout(const Duration(seconds: 10)); + await _appStartEndCompleter.future.timeout( + const Duration(seconds: 10), + ); + } + final appStartEnd = _appStartEnd; + if (appStartEnd != null) { + await _nativeAppStartHandler.call( + hub, + options, + appStartEnd: appStartEnd, + ); } - await _nativeAppStartHandler.call( - hub, - options, - appStartEnd: _appStartEnd, - ); } catch (exception, stackTrace) { options.logger( SentryLevel.error, diff --git a/flutter/lib/src/navigation/sentry_navigator_observer.dart b/flutter/lib/src/navigation/sentry_navigator_observer.dart index 1444a7e92a..3be296ddc1 100644 --- a/flutter/lib/src/navigation/sentry_navigator_observer.dart +++ b/flutter/lib/src/navigation/sentry_navigator_observer.dart @@ -97,14 +97,13 @@ class SentryNavigatorObserver extends RouteObserver> { } /// Initializes the TimeToDisplayTracker with the option to enable time to full display tracing. - TimeToDisplayTracker _initializeTimeToDisplayTracker() { - bool enableTimeToFullDisplayTracing = false; + TimeToDisplayTracker? _initializeTimeToDisplayTracker() { final options = _hub.options; if (options is SentryFlutterOptions) { - enableTimeToFullDisplayTracing = options.enableTimeToFullDisplayTracing; + return options.timeToDisplayTracker; + } else { + return null; } - return TimeToDisplayTracker( - enableTimeToFullDisplayTracing: enableTimeToFullDisplayTracing); } final Hub _hub; @@ -362,7 +361,7 @@ class SentryNavigatorObserver extends RouteObserver> { } if (!isAppStart) { - await _timeToDisplayTracker?.trackRegularRouteTTD( + await _timeToDisplayTracker?.track( transaction, startTimestamp: startTimestamp, ); diff --git a/flutter/lib/src/navigation/time_to_display_tracker.dart b/flutter/lib/src/navigation/time_to_display_tracker.dart index a2c1813317..e906f9eabc 100644 --- a/flutter/lib/src/navigation/time_to_display_tracker.dart +++ b/flutter/lib/src/navigation/time_to_display_tracker.dart @@ -9,38 +9,50 @@ import 'time_to_initial_display_tracker.dart'; @internal class TimeToDisplayTracker { final TimeToInitialDisplayTracker _ttidTracker; - final TimeToFullDisplayTracker? _ttfdTracker; - final bool enableTimeToFullDisplayTracing; + final TimeToFullDisplayTracker _ttfdTracker; + final SentryFlutterOptions options; TimeToDisplayTracker({ TimeToInitialDisplayTracker? ttidTracker, TimeToFullDisplayTracker? ttfdTracker, - required this.enableTimeToFullDisplayTracing, + required this.options, }) : _ttidTracker = ttidTracker ?? TimeToInitialDisplayTracker(), - _ttfdTracker = enableTimeToFullDisplayTracing - ? ttfdTracker ?? TimeToFullDisplayTracker() - : null; - - Future trackRegularRouteTTD(ISentrySpan transaction, - {required DateTime startTimestamp}) async { - await _ttidTracker.trackRegularRoute(transaction, startTimestamp); - await _trackTTFDIfEnabled(transaction, startTimestamp); - } - - Future _trackTTFDIfEnabled( - ISentrySpan transaction, DateTime startTimestamp) async { - if (enableTimeToFullDisplayTracing) { - await _ttfdTracker?.track(transaction, startTimestamp); + _ttfdTracker = ttfdTracker ?? TimeToFullDisplayTracker(); + + Future track( + ISentrySpan transaction, { + required DateTime startTimestamp, + DateTime? endTimestamp, + String? origin, + }) async { + // TTID + await _ttidTracker.track( + transaction: transaction, + startTimestamp: startTimestamp, + endTimestamp: endTimestamp, + origin: origin, + ); + + // TTFD + if (options.enableTimeToFullDisplayTracing) { + await _ttfdTracker.track( + transaction: transaction, + startTimestamp: startTimestamp, + ); } } @internal Future reportFullyDisplayed() async { - return _ttfdTracker?.reportFullyDisplayed(); + if (options.enableTimeToFullDisplayTracing) { + return _ttfdTracker.reportFullyDisplayed(); + } } void clear() { _ttidTracker.clear(); - _ttfdTracker?.clear(); + if (options.enableTimeToFullDisplayTracing) { + _ttfdTracker.clear(); + } } } diff --git a/flutter/lib/src/navigation/time_to_full_display_tracker.dart b/flutter/lib/src/navigation/time_to_full_display_tracker.dart index 385c25c38f..93f291d69a 100644 --- a/flutter/lib/src/navigation/time_to_full_display_tracker.dart +++ b/flutter/lib/src/navigation/time_to_full_display_tracker.dart @@ -37,54 +37,55 @@ class TimeToFullDisplayTracker { EndTimestampProvider _endTimestampProvider = ttidEndTimestampProvider(); Completer _completedTTFDTracking = Completer(); - Future track(ISentrySpan transaction, DateTime startTimestamp) async { + Future track({ + required ISentrySpan transaction, + required DateTime startTimestamp, + }) async { _startTimestamp = startTimestamp; _transaction = transaction as SentryTracer; - _ttfdSpan = transaction.startChild(SentrySpanOperations.uiTimeToFullDisplay, - description: '${transaction.name} full display', - startTimestamp: startTimestamp); + _ttfdSpan = transaction.startChild( + SentrySpanOperations.uiTimeToFullDisplay, + description: '${transaction.name} full display', + startTimestamp: startTimestamp, + ); _ttfdSpan?.origin = SentryTraceOrigins.manualUiTimeToDisplay; // Wait for TTFD to finish - await _completedTTFDTracking.future - .timeout(_autoFinishAfter, onTimeout: handleTimeout); + await _completedTTFDTracking.future.timeout( + _autoFinishAfter, + onTimeout: _handleTimeout, + ); + } - clear(); + Future reportFullyDisplayed() async { + await _complete(getUtcDateTime()); + } + + void _handleTimeout() { + _complete(null); } - void handleTimeout() { + Future _complete(DateTime? timestamp) async { final ttfdSpan = _ttfdSpan; final startTimestamp = _startTimestamp; - final endTimestamp = _endTimestampProvider(); + final endTimestamp = timestamp ?? _endTimestampProvider(); if (ttfdSpan == null || ttfdSpan.finished == true || startTimestamp == null || endTimestamp == null) { _completedTTFDTracking.complete(); + clear(); return; } _setTTFDMeasurement(startTimestamp, endTimestamp); - ttfdSpan.finish( - status: SpanStatus.deadlineExceeded(), endTimestamp: endTimestamp); - - _completedTTFDTracking.complete(); - } - - Future reportFullyDisplayed() async { - final endTimestamp = getUtcDateTime(); - final startTimestamp = _startTimestamp; - final ttfdSpan = _ttfdSpan; - - if (ttfdSpan?.finished == true || startTimestamp == null) { - _completedTTFDTracking.complete(); - return; - } - - _setTTFDMeasurement(startTimestamp, endTimestamp); - await ttfdSpan?.finish(status: SpanStatus.ok(), endTimestamp: endTimestamp); - + await ttfdSpan.finish( + status: + timestamp != null ? SpanStatus.ok() : SpanStatus.deadlineExceeded(), + endTimestamp: endTimestamp, + ); _completedTTFDTracking.complete(); + clear(); } void _setTTFDMeasurement(DateTime startTimestamp, DateTime endTimestamp) { diff --git a/flutter/lib/src/navigation/time_to_initial_display_tracker.dart b/flutter/lib/src/navigation/time_to_initial_display_tracker.dart index 7895ec4fa0..d2bad18690 100644 --- a/flutter/lib/src/navigation/time_to_initial_display_tracker.dart +++ b/flutter/lib/src/navigation/time_to_initial_display_tracker.dart @@ -37,22 +37,17 @@ class TimeToInitialDisplayTracker { @internal DateTime? get endTimestamp => _endTimestamp; - Future trackRegularRoute( - ISentrySpan transaction, - DateTime startTimestamp, - ) async { - await _trackTimeToInitialDisplay( - transaction: transaction, - startTimestamp: startTimestamp, - ); - } - - Future _trackTimeToInitialDisplay({ + Future track({ required ISentrySpan transaction, required DateTime startTimestamp, DateTime? endTimestamp, String? origin, }) async { + if (endTimestamp != null) { + // Store the end timestamp for potential use by TTFD tracking + this._endTimestamp = endTimestamp; + } + final _endTimestamp = endTimestamp ?? await determineEndTime(); if (_endTimestamp == null) return; @@ -73,8 +68,11 @@ class TimeToInitialDisplayTracker { milliseconds: _endTimestamp.difference(startTimestamp).inMilliseconds); final ttidMeasurement = SentryMeasurement.timeToInitialDisplay(duration); - transaction.setMeasurement(ttidMeasurement.name, ttidMeasurement.value, - unit: ttidMeasurement.unit); + transaction.setMeasurement( + ttidMeasurement.name, + ttidMeasurement.value, + unit: ttidMeasurement.unit, + ); await ttidSpan.finish(endTimestamp: _endTimestamp); } diff --git a/flutter/lib/src/sentry_flutter_options.dart b/flutter/lib/src/sentry_flutter_options.dart index 8e533e4384..e400aa3536 100644 --- a/flutter/lib/src/sentry_flutter_options.dart +++ b/flutter/lib/src/sentry_flutter_options.dart @@ -8,6 +8,7 @@ import 'package:sentry/sentry.dart'; import 'package:flutter/widgets.dart'; import 'binding_wrapper.dart'; +import 'navigation/time_to_display_tracker.dart'; import 'renderer/renderer.dart'; import 'screenshot/sentry_screenshot_quality.dart'; import 'event_processor/screenshot_event_processor.dart'; @@ -219,6 +220,11 @@ class SentryFlutterOptions extends SentryOptions { /// This feature requires using the [Routing Instrumentation](https://docs.sentry.io/platforms/flutter/integrations/routing-instrumentation/). bool enableTimeToFullDisplayTracing = false; + @meta.internal + late TimeToDisplayTracker timeToDisplayTracker = TimeToDisplayTracker( + options: this, + ); + /// Sets the Proguard uuid for Android platform. String? proguardUuid; diff --git a/flutter/test/integrations/native_app_start_handler_test.dart b/flutter/test/integrations/native_app_start_handler_test.dart index 925879ea6a..375231a45f 100644 --- a/flutter/test/integrations/native_app_start_handler_test.dart +++ b/flutter/test/integrations/native_app_start_handler_test.dart @@ -42,91 +42,88 @@ void main() { setupMocks(fixture); }); - test('native app start measurement added to first transaction', () async { + test('added transaction has app start measurement', () async { await fixture.call( appStartEnd: DateTime.fromMillisecondsSinceEpoch(10), ); + final transaction = fixture.capturedTransaction(); final measurement = transaction.measurements['app_start_cold']!; expect(measurement.value, 10); expect(measurement.unit, DurationSentryMeasurementUnit.milliSecond); - }); - test('measurements appended', () async { - await fixture.call( - appStartEnd: DateTime.fromMillisecondsSinceEpoch(10), - ); + final spans = transaction.spans; - final measurement = SentryMeasurement.warmAppStart(Duration(seconds: 1)); + final appStartSpan = spans.firstWhereOrNull( + (element) => element.context.description == 'Cold Start'); - final transaction = fixture.capturedTransaction().copyWith(); - transaction.measurements[measurement.name] = measurement; + final pluginRegistrationSpan = spans.firstWhereOrNull((element) => + element.context.description == 'App start to plugin registration'); - expect(transaction.measurements.length, 2); - expect(transaction.measurements.containsKey(measurement.name), true); - }); + final sentrySetupSpan = spans.firstWhereOrNull((element) => + element.context.description == 'Before Sentry Init Setup'); - test('native app start measurement not added if more than 60s', () async { - await fixture.call( - appStartEnd: DateTime.fromMillisecondsSinceEpoch(60001), - ); + final firstFrameRenderSpan = spans.firstWhereOrNull( + (element) => element.context.description == 'First frame render'); - verifyNever(fixture.hub.captureTransaction( - captureAny, - traceContext: captureAnyNamed('traceContext'), - )); + expect(appStartSpan, isNotNull); + expect(pluginRegistrationSpan, isNotNull); + expect(sentrySetupSpan, isNotNull); + expect(firstFrameRenderSpan, isNotNull); }); - test( - 'autoAppStart is false and appStartEnd is not set does not add app start measurement', - () async { - fixture.options.autoAppStart = false; + test('added transaction has ttid measurement', () async { await fixture.call( - appStartEnd: null, + appStartEnd: DateTime.fromMillisecondsSinceEpoch(10), ); - final transaction = fixture.capturedTransaction(); + final transaction = fixture.capturedTransaction().copyWith(); - expect(transaction.measurements.isEmpty, true); - expect(transaction.spans.length, - 1); // Only containing ui.load.initial_display - expect(transaction.spans[0].context.operation, 'ui.load.initial_display'); + final measurement = transaction.measurements['time_to_initial_display']!; + expect(measurement.value, 10); + expect(measurement.unit, DurationSentryMeasurementUnit.milliSecond); }); - test( - 'autoAppStart is false and appStartEnd is set adds app start measurement', - () async { - fixture.options.autoAppStart = false; - + test('added transaction has no ttfd measurement', () async { await fixture.call( appStartEnd: DateTime.fromMillisecondsSinceEpoch(10), ); - final transaction = fixture.capturedTransaction(); + final transaction = fixture.capturedTransaction().copyWith(); - final measurement = transaction.measurements['app_start_cold']!; - expect(measurement.value, 10); - expect(measurement.unit, DurationSentryMeasurementUnit.milliSecond); + final measurement = transaction.measurements['time_to_full_display']; + expect(measurement, isNull); + }); - final spans = transaction.spans; + test('added transaction has ttfd measurement if opt in', () async { + Future.delayed( + const Duration(milliseconds: 100), + () async => + await fixture.options.timeToDisplayTracker.reportFullyDisplayed(), + ); - final appStartSpan = spans.firstWhereOrNull( - (element) => element.context.description == 'Cold Start'); + fixture.options.enableTimeToFullDisplayTracing = true; - final pluginRegistrationSpan = spans.firstWhereOrNull((element) => - element.context.description == 'App start to plugin registration'); + await fixture.call( + appStartEnd: DateTime.fromMillisecondsSinceEpoch(10), + ); - final sentrySetupSpan = spans.firstWhereOrNull((element) => - element.context.description == 'Before Sentry Init Setup'); + final transaction = fixture.capturedTransaction().copyWith(); - final firstFrameRenderSpan = spans.firstWhereOrNull( - (element) => element.context.description == 'First frame render'); + final measurement = transaction.measurements['time_to_full_display']; + expect(measurement, isNotNull); + }); - expect(appStartSpan, isNotNull); - expect(pluginRegistrationSpan, isNotNull); - expect(sentrySetupSpan, isNotNull); - expect(firstFrameRenderSpan, isNotNull); + test('no transaction if app start takes more than 60s', () async { + await fixture.call( + appStartEnd: DateTime.fromMillisecondsSinceEpoch(60001), + ); + + verifyNever(fixture.hub.captureTransaction( + captureAny, + traceContext: captureAnyNamed('traceContext'), + )); }); }); @@ -334,7 +331,7 @@ class Fixture { SentryFlutter.sentrySetupStartTime = DateTime.now().toUtc(); } - Future call({DateTime? appStartEnd}) async { + Future call({required DateTime appStartEnd}) async { await sut.call(hub, options, appStartEnd: appStartEnd); } diff --git a/flutter/test/navigation/time_to_display_tracker_test.dart b/flutter/test/navigation/time_to_display_tracker_test.dart index 79f2d377d9..b77f12d082 100644 --- a/flutter/test/navigation/time_to_display_tracker_test.dart +++ b/flutter/test/navigation/time_to_display_tracker_test.dart @@ -37,89 +37,78 @@ void main() { } group('time to initial display', () { - group('in root screen app start route', () { - test('matches startTimestamp of transaction', () async { - final sut = fixture.getSut(); + test('matches startTimestamp of transaction', () async { + final sut = fixture.getSut(); - final transaction = fixture.getTransaction(name: '/') as SentryTracer; - await sut.trackRegularRouteTTD(transaction, - startTimestamp: fixture.startTimestamp); + final transaction = fixture.getTransaction() as SentryTracer; + await sut.track(transaction, startTimestamp: fixture.startTimestamp); - final ttidSpan = _getTTIDSpan(transaction); - expect(transaction, isNotNull); - expect(transaction.context.operation, SentrySpanOperations.uiLoad); - expect(transaction.startTimestamp, ttidSpan?.startTimestamp); - }); + final ttidSpan = _getTTIDSpan(transaction); + expect(transaction, isNotNull); + expect(transaction.context.operation, SentrySpanOperations.uiLoad); + expect(transaction.startTimestamp, ttidSpan?.startTimestamp); + }); + + test('matches provided endTimestamp', () async { + final sut = fixture.getSut(); + + final transaction = fixture.getTransaction() as SentryTracer; + final start = fixture.startTimestamp; + final end = fixture.startTimestamp.add(Duration(milliseconds: 100)); + await sut.track(transaction, startTimestamp: start, endTimestamp: end); + + final ttidSpan = _getTTIDSpan(transaction); + expect(transaction, isNotNull); + expect(ttidSpan?.endTimestamp, end); }); - group('in regular routes', () { - test('matches startTimestamp of transaction', () async { + group('with approximation strategy', () { + test('finishes ttid span', () async { final sut = fixture.getSut(); final transaction = fixture.getTransaction() as SentryTracer; - await sut.trackRegularRouteTTD(transaction, - startTimestamp: fixture.startTimestamp); + await sut.track(transaction, startTimestamp: fixture.startTimestamp); final ttidSpan = _getTTIDSpan(transaction); - expect(transaction, isNotNull); - expect(transaction.context.operation, SentrySpanOperations.uiLoad); - expect(transaction.startTimestamp, ttidSpan?.startTimestamp); + expect(ttidSpan?.context.operation, + SentrySpanOperations.uiTimeToInitialDisplay); + expect(ttidSpan?.finished, isTrue); + expect(ttidSpan?.origin, SentryTraceOrigins.autoUiTimeToDisplay); }); - group('with approximation strategy', () { - test('finishes ttid span', () async { - final sut = fixture.getSut(); - - final transaction = fixture.getTransaction() as SentryTracer; - await sut.trackRegularRouteTTD(transaction, - startTimestamp: fixture.startTimestamp); + test('completes with timeout when not completing the tracking', () async { + final sut = fixture.getSut(triggerApproximationTimeout: true); - final ttidSpan = _getTTIDSpan(transaction); - expect(ttidSpan?.context.operation, - SentrySpanOperations.uiTimeToInitialDisplay); - expect(ttidSpan?.finished, isTrue); - expect(ttidSpan?.origin, SentryTraceOrigins.autoUiTimeToDisplay); - }); + final transaction = fixture.getTransaction() as SentryTracer; + await sut.track(transaction, startTimestamp: fixture.startTimestamp); + }); + }); - test('completes with timeout when not completing the tracking', - () async { - final sut = fixture.getSut(triggerApproximationTimeout: true); + group('with manual strategy', () { + test('finishes ttid span', () async { + final sut = fixture.getSut(); - final transaction = fixture.getTransaction() as SentryTracer; - await sut.trackRegularRouteTTD(transaction, - startTimestamp: fixture.startTimestamp); + Future.delayed(const Duration(milliseconds: 1), () { + fixture.ttidTracker?.markAsManual(); + fixture.ttidTracker?.completeTracking(); }); - }); + final transaction = fixture.getTransaction() as SentryTracer; + await sut.track(transaction, startTimestamp: fixture.startTimestamp); - group('with manual strategy', () { - test('finishes ttid span', () async { - final sut = fixture.getSut(); - - Future.delayed(const Duration(milliseconds: 1), () { - fixture.ttidTracker?.markAsManual(); - fixture.ttidTracker?.completeTracking(); - }); - final transaction = fixture.getTransaction() as SentryTracer; - await sut.trackRegularRouteTTD(transaction, - startTimestamp: fixture.startTimestamp); - - final ttidSpan = _getTTIDSpan(transaction); - expect(ttidSpan, isNotNull); - expect(ttidSpan?.finished, isTrue); - expect(ttidSpan?.origin, SentryTraceOrigins.manualUiTimeToDisplay); - }); + final ttidSpan = _getTTIDSpan(transaction); + expect(ttidSpan, isNotNull); + expect(ttidSpan?.finished, isTrue); + expect(ttidSpan?.origin, SentryTraceOrigins.manualUiTimeToDisplay); + }); - test('completes with timeout when not completing the tracking', - () async { - final sut = fixture.getSut(); + test('completes with timeout when not completing the tracking', () async { + final sut = fixture.getSut(); - fixture.ttidTracker?.markAsManual(); - // Not calling completeTracking() triggers the manual timeout + fixture.ttidTracker?.markAsManual(); + // Not calling completeTracking() triggers the manual timeout - final transaction = fixture.getTransaction() as SentryTracer; - await sut.trackRegularRouteTTD(transaction, - startTimestamp: fixture.startTimestamp); - }); + final transaction = fixture.getTransaction() as SentryTracer; + await sut.track(transaction, startTimestamp: fixture.startTimestamp); }); }); }); @@ -129,25 +118,22 @@ void main() { fixture.options.enableTimeToFullDisplayTracing = true; }); - group('in regular routes', () { - test( - 'finishes span after timeout with deadline exceeded and ttid matching end time', - () async { - final sut = fixture.getSut(); - final transaction = fixture.getTransaction() as SentryTracer; + test( + 'finishes span after timeout with deadline exceeded and ttid matching end time', + () async { + final sut = fixture.getSut(); + final transaction = fixture.getTransaction() as SentryTracer; - await sut.trackRegularRouteTTD(transaction, - startTimestamp: fixture.startTimestamp); + await sut.track(transaction, startTimestamp: fixture.startTimestamp); - final ttidSpan = _getTTIDSpan(transaction); - expect(ttidSpan, isNotNull); + final ttidSpan = _getTTIDSpan(transaction); + expect(ttidSpan, isNotNull); - final ttfdSpan = _getTTFDSpan(transaction); - expect(ttfdSpan?.finished, isTrue); - expect(ttfdSpan?.status, SpanStatus.deadlineExceeded()); - expect(ttfdSpan?.endTimestamp, ttidSpan?.endTimestamp); - expect(ttfdSpan?.startTimestamp, ttidSpan?.startTimestamp); - }); + final ttfdSpan = _getTTFDSpan(transaction); + expect(ttfdSpan?.finished, isTrue); + expect(ttfdSpan?.status, SpanStatus.deadlineExceeded()); + expect(ttfdSpan?.endTimestamp, ttidSpan?.endTimestamp); + expect(ttfdSpan?.startTimestamp, ttidSpan?.startTimestamp); }); test('multiple ttfd timeouts have correct ttid matching end time', @@ -156,8 +142,7 @@ void main() { final transaction = fixture.getTransaction() as SentryTracer; // First ttfd timeout - await sut.trackRegularRouteTTD(transaction, - startTimestamp: fixture.startTimestamp); + await sut.track(transaction, startTimestamp: fixture.startTimestamp); final ttidSpanA = _getTTIDSpan(transaction); expect(ttidSpanA, isNotNull); @@ -169,8 +154,7 @@ void main() { expect(ttfdSpanA?.startTimestamp, ttidSpanA?.startTimestamp); // Second ttfd timeout - await sut.trackRegularRouteTTD(transaction, - startTimestamp: fixture.startTimestamp); + await sut.track(transaction, startTimestamp: fixture.startTimestamp); final ttidSpanB = _getTTIDSpan(transaction); expect(ttidSpanB, isNotNull); @@ -189,8 +173,7 @@ void main() { final transaction = fixture.getTransaction() as SentryTracer; - await sut.trackRegularRouteTTD(transaction, - startTimestamp: fixture.startTimestamp); + await sut.track(transaction, startTimestamp: fixture.startTimestamp); final ttfdSpan = transaction.children.firstWhereOrNull((element) => element.context.operation == @@ -203,8 +186,7 @@ void main() { final sut = fixture.getSut(); final transaction = fixture.getTransaction() as SentryTracer; - await sut.trackRegularRouteTTD(transaction, - startTimestamp: fixture.startTimestamp); + await sut.track(transaction, startTimestamp: fixture.startTimestamp); expect(transaction, isNotNull); expect(transaction.context.operation, SentrySpanOperations.uiLoad); @@ -239,7 +221,7 @@ class Fixture { return TimeToDisplayTracker( ttidTracker: ttidTracker, ttfdTracker: ttfdTracker, - enableTimeToFullDisplayTracing: options.enableTimeToFullDisplayTracing, + options: options, ); } } diff --git a/flutter/test/navigation/time_to_full_display_tracker_test.dart b/flutter/test/navigation/time_to_full_display_tracker_test.dart index 95d5a3ee25..d3fa71878d 100644 --- a/flutter/test/navigation/time_to_full_display_tracker_test.dart +++ b/flutter/test/navigation/time_to_full_display_tracker_test.dart @@ -23,7 +23,10 @@ void main() { sut.reportFullyDisplayed(); }); - await sut.track(transaction, fixture.startTimestamp); + await sut.track( + transaction: transaction, + startTimestamp: fixture.startTimestamp, + ); final ttfdSpan = transaction.children.first; expect(transaction.children, hasLength(1)); @@ -49,7 +52,10 @@ void main() { final sut = fixture.getSut(); final transaction = fixture.getTransaction() as SentryTracer; - await sut.track(transaction, fixture.startTimestamp); + await sut.track( + transaction: transaction, + startTimestamp: fixture.startTimestamp, + ); final ttfdSpan = transaction.children.first; expect(transaction.children, hasLength(1)); diff --git a/flutter/test/navigation/time_to_initial_display_tracker_test.dart b/flutter/test/navigation/time_to_initial_display_tracker_test.dart index b73e9d4d56..74793af362 100644 --- a/flutter/test/navigation/time_to_initial_display_tracker_test.dart +++ b/flutter/test/navigation/time_to_initial_display_tracker_test.dart @@ -22,12 +22,15 @@ void main() { sut.clear(); }); - group('regular route', () { + group('track', () { test( 'approximation tracking creates and finishes ttid span with correct measurements', () async { final transaction = fixture.getTransaction() as SentryTracer; - await sut.trackRegularRoute(transaction, fixture.startTimestamp); + await sut.track( + transaction: transaction, + startTimestamp: fixture.startTimestamp, + ); final children = transaction.children; expect(children, hasLength(1)); @@ -61,7 +64,10 @@ void main() { }); final transaction = fixture.getTransaction() as SentryTracer; - await sut.trackRegularRoute(transaction, fixture.startTimestamp); + await sut.track( + transaction: transaction, + startTimestamp: fixture.startTimestamp, + ); final children = transaction.children; expect(children, hasLength(1)); @@ -92,7 +98,10 @@ void main() { }); final transaction = fixture.getTransaction() as SentryTracer; - await sut.trackRegularRoute(transaction, fixture.startTimestamp); + await sut.track( + transaction: transaction, + startTimestamp: fixture.startTimestamp, + ); final children = transaction.children; expect(children, hasLength(1)); @@ -115,6 +124,44 @@ void main() { .difference(ttidSpan.startTimestamp) .inMilliseconds); }); + + test('providing endTimestamp finishes transaction with it', () async { + final transaction = fixture.getTransaction() as SentryTracer; + final endTimestamp = + fixture.startTimestamp.add(Duration(milliseconds: 100)); + + await sut.track( + transaction: transaction, + startTimestamp: fixture.startTimestamp, + endTimestamp: endTimestamp, + ); + + final children = transaction.children; + expect(children, hasLength(1)); + + final ttidSpan = transaction.children.first; + expect(endTimestamp, ttidSpan.endTimestamp); + + final ttidMeasurement = + transaction.measurements['time_to_initial_display']; + + expect(ttidMeasurement, isNotNull); + expect(ttidMeasurement?.unit, DurationSentryMeasurementUnit.milliSecond); + expect(ttidMeasurement?.value, greaterThanOrEqualTo(100)); + }); + + test('providing endTimestamp sets endTimestamp ivar', () async { + final transaction = fixture.getTransaction() as SentryTracer; + final endTimestamp = fixture.startTimestamp.add(Duration(seconds: 1)); + + await sut.track( + transaction: transaction, + startTimestamp: fixture.startTimestamp, + endTimestamp: endTimestamp, + ); + + expect(sut.endTimestamp, endTimestamp); + }); }); group('determineEndtime', () { diff --git a/flutter/test/sentry_navigator_observer_test.dart b/flutter/test/sentry_navigator_observer_test.dart index b71abd847d..407bed316f 100644 --- a/flutter/test/sentry_navigator_observer_test.dart +++ b/flutter/test/sentry_navigator_observer_test.dart @@ -1052,7 +1052,7 @@ class Fixture { TimeToInitialDisplayTracker(frameCallbackHandler: frameCallbackHandler); final timeToDisplayTracker = TimeToDisplayTracker( ttidTracker: timeToInitialDisplayTracker, - enableTimeToFullDisplayTracing: enableTimeToFullDisplayTracing, + options: hub.options as SentryFlutterOptions, ); return SentryNavigatorObserver( hub: hub, From 76f9cc3bfd6082c1f994705635460dd1aa917c91 Mon Sep 17 00:00:00 2001 From: Denis Andrasec Date: Mon, 7 Oct 2024 16:50:39 +0200 Subject: [PATCH 2/7] add chengelog entry --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 644e108461..66c973b6db 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -21,6 +21,7 @@ - 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)) +- Start missing TTFD for root screen transaction ([#2332](https://github.com/getsentry/sentry-dart/pull/2332)) ### Deprecate From 169b8139baaa90939d46cad997e598d587db332b Mon Sep 17 00:00:00 2001 From: Denis Andrasec Date: Mon, 7 Oct 2024 16:58:22 +0200 Subject: [PATCH 3/7] cleanup --- .../native_app_start_handler.dart | 36 +++++++------------ 1 file changed, 13 insertions(+), 23 deletions(-) diff --git a/flutter/lib/src/integrations/native_app_start_handler.dart b/flutter/lib/src/integrations/native_app_start_handler.dart index ae2a546361..4ce177a9ce 100644 --- a/flutter/lib/src/integrations/native_app_start_handler.dart +++ b/flutter/lib/src/integrations/native_app_start_handler.dart @@ -43,12 +43,12 @@ class NativeAppStartHandler { startTimestamp: appStartInfo.start, ); - await options.timeToDisplayTracker.track(transaction, - startTimestamp: appStartInfo.start, - endTimestamp: appStartInfo.end, - origin: SentryTraceOrigins.autoUiTimeToDisplay); - - // Enrich Transaction + await options.timeToDisplayTracker.track( + transaction, + startTimestamp: appStartInfo.start, + endTimestamp: appStartInfo.end, + origin: SentryTraceOrigins.autoUiTimeToDisplay, + ); SentryTracer sentryTracer; if (transaction is SentryTracer) { @@ -57,11 +57,10 @@ class NativeAppStartHandler { return; } + // Enrich Transaction SentryMeasurement? measurement = appStartInfo.toMeasurement(); - if (measurement != null) { - sentryTracer.measurements[measurement.name] = measurement; - await _attachAppStartSpans(appStartInfo, sentryTracer); - } + sentryTracer.measurements[measurement.name] = appStartInfo.toMeasurement(); + await _attachAppStartSpans(appStartInfo, sentryTracer); // Finish Transaction await transaction.finish(endTimestamp: appStartInfo.end); @@ -131,9 +130,6 @@ class NativeAppStartHandler { _AppStartInfo appStartInfo, SentryTracer transaction) async { final transactionTraceId = transaction.context.traceId; final appStartEnd = appStartInfo.end; - if (appStartEnd == null) { - return; - } final appStartSpan = await _createAndFinishSpan( tracer: transaction, @@ -242,30 +238,24 @@ class _AppStartInfo { _AppStartInfo( this.type, { required this.start, + required this.end, required this.pluginRegistration, required this.sentrySetupStart, required this.nativeSpanTimes, - this.end, }); final _AppStartType type; final DateTime start; + final DateTime end; final List<_TimeSpan> nativeSpanTimes; - // We allow the end to be null, since it might be set at a later time - // with setAppStartEnd when autoAppStart is disabled - DateTime? end; - final DateTime pluginRegistration; final DateTime sentrySetupStart; - Duration? get duration => end?.difference(start); + Duration get duration => end.difference(start); - SentryMeasurement? toMeasurement() { + SentryMeasurement toMeasurement() { final duration = this.duration; - if (duration == null) { - return null; - } return type == _AppStartType.cold ? SentryMeasurement.coldAppStart(duration) : SentryMeasurement.warmAppStart(duration); From c12cab3b51088c5571dc8cf14fa65d3b118d795f Mon Sep 17 00:00:00 2001 From: Denis Andrasec Date: Tue, 8 Oct 2024 10:23:50 +0200 Subject: [PATCH 4/7] use options clock for app start end --- .../src/integrations/native_app_start_integration.dart | 9 +++++++-- .../integrations/native_app_start_integration_test.dart | 5 +---- 2 files changed, 8 insertions(+), 6 deletions(-) diff --git a/flutter/lib/src/integrations/native_app_start_integration.dart b/flutter/lib/src/integrations/native_app_start_integration.dart index 77a4139881..db3388e74e 100644 --- a/flutter/lib/src/integrations/native_app_start_integration.dart +++ b/flutter/lib/src/integrations/native_app_start_integration.dart @@ -33,12 +33,17 @@ class NativeAppStartIntegration extends Integration { void call(Hub hub, SentryFlutterOptions options) async { _frameCallbackHandler.addPostFrameCallback((timeStamp) async { try { - if (!options.autoAppStart && _appStartEnd == null) { + DateTime? appStartEnd; + if (options.autoAppStart) { + appStartEnd = options.clock(); + } else if (_appStartEnd == null) { await _appStartEndCompleter.future.timeout( const Duration(seconds: 10), ); + appStartEnd = _appStartEnd; + } else { + appStartEnd = null; } - final appStartEnd = _appStartEnd; if (appStartEnd != null) { await _nativeAppStartHandler.call( hub, diff --git a/flutter/test/integrations/native_app_start_integration_test.dart b/flutter/test/integrations/native_app_start_integration_test.dart index 02dbee7116..066b5d3b7e 100644 --- a/flutter/test/integrations/native_app_start_integration_test.dart +++ b/flutter/test/integrations/native_app_start_integration_test.dart @@ -40,14 +40,11 @@ void main() { () async { fixture.callIntegration(); - final appStartEnd = DateTime.fromMicrosecondsSinceEpoch(50); - fixture.sut.appStartEnd = appStartEnd; - final postFrameCallback = fixture.frameCallbackHandler.postFrameCallback!; postFrameCallback(Duration(seconds: 0)); expect(fixture.nativeAppStartHandler.calls, 1); - expect(fixture.nativeAppStartHandler.appStartEnd, appStartEnd); + expect(fixture.nativeAppStartHandler.appStartEnd, isNotNull); }); test( From 7d08c83162eefc292754a1d9bb013cbe6230e79b Mon Sep 17 00:00:00 2001 From: Denis Andrasec Date: Tue, 8 Oct 2024 10:44:39 +0200 Subject: [PATCH 5/7] use timeToDisplayTracker from options, remove timeToDisplayTracker from navigator ctor --- .../navigation/sentry_navigator_observer.dart | 10 ++-------- flutter/lib/src/sentry_flutter.dart | 8 +++++++- flutter/test/sentry_navigator_observer_test.dart | 16 +++++++++------- 3 files changed, 18 insertions(+), 16 deletions(-) diff --git a/flutter/lib/src/navigation/sentry_navigator_observer.dart b/flutter/lib/src/navigation/sentry_navigator_observer.dart index 3be296ddc1..2279d6e434 100644 --- a/flutter/lib/src/navigation/sentry_navigator_observer.dart +++ b/flutter/lib/src/navigation/sentry_navigator_observer.dart @@ -78,7 +78,6 @@ class SentryNavigatorObserver extends RouteObserver> { bool setRouteNameAsTransaction = false, RouteNameExtractor? routeNameExtractor, AdditionalInfoExtractor? additionalInfoProvider, - @visibleForTesting TimeToDisplayTracker? timeToDisplayTracker, List? ignoreRoutes, }) : _hub = hub ?? HubAdapter(), _enableAutoTransactions = enableAutoTransactions, @@ -92,8 +91,7 @@ class SentryNavigatorObserver extends RouteObserver> { if (enableAutoTransactions) { _hub.options.sdk.addIntegration('UINavigationTracing'); } - _timeToDisplayTracker = - timeToDisplayTracker ?? _initializeTimeToDisplayTracker(); + _timeToDisplayTracker = _initializeTimeToDisplayTracker(); } /// Initializes the TimeToDisplayTracker with the option to enable time to full display tracing. @@ -114,11 +112,7 @@ class SentryNavigatorObserver extends RouteObserver> { final AdditionalInfoExtractor? _additionalInfoProvider; final SentryNativeBinding? _native; final List _ignoreRoutes; - static TimeToDisplayTracker? _timeToDisplayTracker; - - @internal - static TimeToDisplayTracker? get timeToDisplayTracker => - _timeToDisplayTracker; + TimeToDisplayTracker? _timeToDisplayTracker; ISentrySpan? _transaction; diff --git a/flutter/lib/src/sentry_flutter.dart b/flutter/lib/src/sentry_flutter.dart index e190115149..ee68d01f9f 100644 --- a/flutter/lib/src/sentry_flutter.dart +++ b/flutter/lib/src/sentry_flutter.dart @@ -242,7 +242,13 @@ mixin SentryFlutter { /// Reports the time it took for the screen to be fully displayed. /// This requires the [SentryFlutterOptions.enableTimeToFullDisplayTracing] option to be set to `true`. static Future reportFullyDisplayed() async { - return SentryNavigatorObserver.timeToDisplayTracker?.reportFullyDisplayed(); + // ignore: invalid_use_of_internal_member + final options = Sentry.currentHub.options; + if (options is SentryFlutterOptions) { + return options.timeToDisplayTracker.reportFullyDisplayed(); + } else { + return; + } } /// Pauses the app hang tracking. diff --git a/flutter/test/sentry_navigator_observer_test.dart b/flutter/test/sentry_navigator_observer_test.dart index 407bed316f..407496874a 100644 --- a/flutter/test/sentry_navigator_observer_test.dart +++ b/flutter/test/sentry_navigator_observer_test.dart @@ -1044,16 +1044,19 @@ class Fixture { bool setRouteNameAsTransaction = false, RouteNameExtractor? routeNameExtractor, AdditionalInfoExtractor? additionalInfoProvider, - bool enableTimeToFullDisplayTracing = false, List? ignoreRoutes, }) { final frameCallbackHandler = FakeFrameCallbackHandler(); - final timeToInitialDisplayTracker = - TimeToInitialDisplayTracker(frameCallbackHandler: frameCallbackHandler); - final timeToDisplayTracker = TimeToDisplayTracker( - ttidTracker: timeToInitialDisplayTracker, - options: hub.options as SentryFlutterOptions, + final timeToInitialDisplayTracker = TimeToInitialDisplayTracker( + frameCallbackHandler: frameCallbackHandler, ); + final options = hub.options; + if (options is SentryFlutterOptions) { + options.timeToDisplayTracker = TimeToDisplayTracker( + ttidTracker: timeToInitialDisplayTracker, + options: hub.options as SentryFlutterOptions, + ); + } return SentryNavigatorObserver( hub: hub, enableAutoTransactions: enableAutoTransactions, @@ -1061,7 +1064,6 @@ class Fixture { setRouteNameAsTransaction: setRouteNameAsTransaction, routeNameExtractor: routeNameExtractor, additionalInfoProvider: additionalInfoProvider, - timeToDisplayTracker: timeToDisplayTracker, ignoreRoutes: ignoreRoutes, ); } From 9be8814b98d16b957edad5a469a9c4810add3658 Mon Sep 17 00:00:00 2001 From: GIancarlo Buenaflor Date: Fri, 11 Oct 2024 02:39:35 +0200 Subject: [PATCH 6/7] fix test --- flutter/test/navigation/time_to_full_display_tracker_test.dart | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/flutter/test/navigation/time_to_full_display_tracker_test.dart b/flutter/test/navigation/time_to_full_display_tracker_test.dart index 1cdad389de..a2adf62aeb 100644 --- a/flutter/test/navigation/time_to_full_display_tracker_test.dart +++ b/flutter/test/navigation/time_to_full_display_tracker_test.dart @@ -78,7 +78,8 @@ void main() { sut.reportFullyDisplayed(); }); - await sut.track(transaction, fixture.startTimestamp); + await sut.track( + transaction: transaction, startTimestamp: fixture.startTimestamp); }); test('finishing ttfd without starting tracker does not throw', () async { From ab11fff3c6a61e4a5f8bf857b0f20a019c0f38d5 Mon Sep 17 00:00:00 2001 From: GIancarlo Buenaflor Date: Fri, 11 Oct 2024 02:47:22 +0200 Subject: [PATCH 7/7] fix analyze --- flutter/lib/src/integrations/native_app_start_integration.dart | 1 + 1 file changed, 1 insertion(+) diff --git a/flutter/lib/src/integrations/native_app_start_integration.dart b/flutter/lib/src/integrations/native_app_start_integration.dart index db3388e74e..03cf15329f 100644 --- a/flutter/lib/src/integrations/native_app_start_integration.dart +++ b/flutter/lib/src/integrations/native_app_start_integration.dart @@ -35,6 +35,7 @@ class NativeAppStartIntegration extends Integration { try { DateTime? appStartEnd; if (options.autoAppStart) { + // ignore: invalid_use_of_internal_member appStartEnd = options.clock(); } else if (_appStartEnd == null) { await _appStartEndCompleter.future.timeout(