diff --git a/CHANGELOG.md b/CHANGELOG.md index 61466b08f..644e10846 100644 --- 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 index 0554c0ad2..1444a7e92 100644 --- 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> { // 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> { 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> { await _native?.beginNativeFrames(); } - Future _finishTimeToDisplayTracking({bool clearAfter = false}) async { + Future _finishTimeToDisplayTracking( + {required DateTime endTimestamp, bool clearAfter = false}) async { final transaction = _transaction; _transaction = null; try { @@ -317,7 +321,10 @@ class SentryNavigatorObserver extends RouteObserver> { 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,14 +338,15 @@ class SentryNavigatorObserver extends RouteObserver> { rethrow; } } finally { - await transaction?.finish(); + await transaction?.finish(endTimestamp: endTimestamp); if (clearAfter) { _clear(); } } } - Future _startTimeToDisplayTracking(Route? route) async { + Future _startTimeToDisplayTracking( + Route? route, DateTime startTimestamp) async { try { final routeName = _getRouteName(route) ?? _currentRouteName; if (!_enableAutoTransactions || routeName == null) { @@ -346,8 +354,6 @@ class SentryNavigatorObserver extends RouteObserver> { } 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 index 051d0602b..7895ec4fa 100644 --- 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? _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 index 526343a8b..b73e9d4d5 100644 --- 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 index 6d487a3b4..b71abd847 100644 --- 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.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.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); });