diff --git a/CHANGELOG.md b/CHANGELOG.md index 0bc2f45ab2..0df11587c9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ ### Features +- Capture total frames, frames delay, slow & frozen frames and attach to spans ([#2106](https://github.com/getsentry/sentry-dart/pull/2106)) - Support WebAssembly compilation (dart2wasm) ([#2113](https://github.com/getsentry/sentry-dart/pull/2113)) ### Dependencies diff --git a/dart/lib/sentry.dart b/dart/lib/sentry.dart index f416d0b797..fd88a49fc5 100644 --- a/dart/lib/sentry.dart +++ b/dart/lib/sentry.dart @@ -30,6 +30,7 @@ export 'src/http_client/sentry_http_client_error.dart'; export 'src/sentry_attachment/sentry_attachment.dart'; export 'src/sentry_user_feedback.dart'; export 'src/utils/tracing_utils.dart'; +export 'src/performance_collector.dart'; // tracing export 'src/tracing.dart'; export 'src/hint.dart'; diff --git a/dart/lib/src/performance_collector.dart b/dart/lib/src/performance_collector.dart new file mode 100644 index 0000000000..736534fb03 --- /dev/null +++ b/dart/lib/src/performance_collector.dart @@ -0,0 +1,13 @@ +import '../sentry.dart'; + +abstract class PerformanceCollector {} + +/// Used for collecting continuous data about vitals (slow, frozen frames, etc.) +/// during a transaction/span. +abstract class PerformanceContinuousCollector extends PerformanceCollector { + Future onSpanStarted(ISentrySpan span); + + Future onSpanFinished(ISentrySpan span, DateTime endTimestamp); + + void clear(); +} diff --git a/dart/lib/src/protocol/sentry_span.dart b/dart/lib/src/protocol/sentry_span.dart index 780578d182..6358b4802a 100644 --- a/dart/lib/src/protocol/sentry_span.dart +++ b/dart/lib/src/protocol/sentry_span.dart @@ -1,12 +1,11 @@ import 'dart:async'; -import '../hub.dart'; +import 'package:meta/meta.dart'; + +import '../../sentry.dart'; import '../metrics/local_metrics_aggregator.dart'; -import '../protocol.dart'; import '../sentry_tracer.dart'; -import '../tracing.dart'; -import '../utils.dart'; typedef OnFinishedCallback = Future Function({DateTime? endTimestamp}); @@ -17,7 +16,15 @@ class SentrySpan extends ISentrySpan { late final DateTime _startTimestamp; final Hub _hub; + bool _isRootSpan = false; + + bool get isRootSpan => _isRootSpan; + + @internal + SentryTracer get tracer => _tracer; + final SentryTracer _tracer; + final Map _data = {}; dynamic _throwable; @@ -36,6 +43,7 @@ class SentrySpan extends ISentrySpan { DateTime? startTimestamp, this.samplingDecision, OnFinishedCallback? finishedCallback, + isRootSpan = false, }) { _startTimestamp = startTimestamp?.toUtc() ?? _hub.options.clock(); _finishedCallback = finishedCallback; @@ -43,6 +51,7 @@ class SentrySpan extends ISentrySpan { _localMetricsAggregator = _hub.options.enableSpanLocalMetricAggregation ? LocalMetricsAggregator() : null; + _isRootSpan = isRootSpan; } @override @@ -56,17 +65,27 @@ class SentrySpan extends ISentrySpan { } if (endTimestamp == null) { - _endTimestamp = _hub.options.clock(); + endTimestamp = _hub.options.clock(); } else if (endTimestamp.isBefore(_startTimestamp)) { _hub.options.logger( SentryLevel.warning, 'End timestamp ($endTimestamp) cannot be before start timestamp ($_startTimestamp)', ); - _endTimestamp = _hub.options.clock(); + endTimestamp = _hub.options.clock(); } else { - _endTimestamp = endTimestamp.toUtc(); + endTimestamp = endTimestamp.toUtc(); } + for (final collector in _hub.options.performanceCollectors) { + if (collector is PerformanceContinuousCollector) { + await collector.onSpanFinished(this, endTimestamp); + } + } + + // The finished flag depends on the _endTimestamp + // If we set this earlier then finished is true and then we cannot use setData etc... + _endTimestamp = endTimestamp; + // associate error if (_throwable != null) { _hub.setSpanContext(_throwable, this, _tracer.name); diff --git a/dart/lib/src/sentry_options.dart b/dart/lib/src/sentry_options.dart index 956f81c056..f3f3c65a50 100644 --- a/dart/lib/src/sentry_options.dart +++ b/dart/lib/src/sentry_options.dart @@ -501,6 +501,14 @@ class SentryOptions { return tracesSampleRate != null || tracesSampler != null; } + List get performanceCollectors => + _performanceCollectors; + final List _performanceCollectors = []; + + void addPerformanceCollector(PerformanceCollector collector) { + _performanceCollectors.add(collector); + } + @internal late SentryExceptionFactory exceptionFactory = SentryExceptionFactory(this); diff --git a/dart/lib/src/sentry_tracer.dart b/dart/lib/src/sentry_tracer.dart index 2326db0716..350552a9ee 100644 --- a/dart/lib/src/sentry_tracer.dart +++ b/dart/lib/src/sentry_tracer.dart @@ -69,6 +69,7 @@ class SentryTracer extends ISentrySpan { _hub, samplingDecision: transactionContext.samplingDecision, startTimestamp: startTimestamp, + isRootSpan: true, ); _waitForChildren = waitForChildren; _autoFinishAfter = autoFinishAfter; @@ -80,6 +81,12 @@ class SentryTracer extends ISentrySpan { SentryTransactionNameSource.custom; _trimEnd = trimEnd; _onFinish = onFinish; + + for (final collector in _hub.options.performanceCollectors) { + if (collector is PerformanceContinuousCollector) { + collector.onSpanStarted(_rootSpan); + } + } } @override @@ -256,6 +263,12 @@ class SentryTracer extends ISentrySpan { _children.add(child); + for (final collector in _hub.options.performanceCollectors) { + if (collector is PerformanceContinuousCollector) { + collector.onSpanStarted(child); + } + } + return child; } diff --git a/flutter/android/src/main/kotlin/io/sentry/flutter/SentryFlutterPlugin.kt b/flutter/android/src/main/kotlin/io/sentry/flutter/SentryFlutterPlugin.kt index 424e51c6b7..26b84a6f5d 100644 --- a/flutter/android/src/main/kotlin/io/sentry/flutter/SentryFlutterPlugin.kt +++ b/flutter/android/src/main/kotlin/io/sentry/flutter/SentryFlutterPlugin.kt @@ -2,6 +2,7 @@ package io.sentry.flutter import android.app.Activity import android.content.Context +import android.os.Build import android.util.Log import io.flutter.embedding.engine.plugins.FlutterPlugin import io.flutter.embedding.engine.plugins.activity.ActivityAware @@ -72,6 +73,7 @@ class SentryFlutterPlugin : FlutterPlugin, MethodCallHandler, ActivityAware { "setTag" -> setTag(call.argument("key"), call.argument("value"), result) "removeTag" -> removeTag(call.argument("key"), result) "loadContexts" -> loadContexts(result) + "displayRefreshRate" -> displayRefreshRate(result) else -> result.notImplemented() } } @@ -179,6 +181,29 @@ class SentryFlutterPlugin : FlutterPlugin, MethodCallHandler, ActivityAware { } } + private fun displayRefreshRate(result: Result) { + var refreshRate: Int? = null + + if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.R) { + val display = activity?.get()?.display + if (display != null) { + refreshRate = display.refreshRate.toInt() + } + } else { + val display = + activity + ?.get() + ?.window + ?.windowManager + ?.defaultDisplay + if (display != null) { + refreshRate = display.refreshRate.toInt() + } + } + + result.success(refreshRate) + } + private fun TimeSpan.addToMap(map: MutableMap) { if (startTimestamp == null) return diff --git a/flutter/ios/Classes/SentryFlutterPluginApple.swift b/flutter/ios/Classes/SentryFlutterPluginApple.swift index fc8fb42f9c..cee6266564 100644 --- a/flutter/ios/Classes/SentryFlutterPluginApple.swift +++ b/flutter/ios/Classes/SentryFlutterPluginApple.swift @@ -5,6 +5,7 @@ import UIKit #elseif os(macOS) import FlutterMacOS import AppKit +import CoreVideo #endif // swiftlint:disable file_length function_body_length @@ -164,6 +165,9 @@ public class SentryFlutterPluginApple: NSObject, FlutterPlugin { collectProfile(call, result) #endif + case "displayRefreshRate": + displayRefreshRate(result) + default: result(FlutterMethodNotImplemented) } @@ -651,6 +655,64 @@ public class SentryFlutterPluginApple: NSObject, FlutterPlugin { PrivateSentrySDKOnly.discardProfiler(forTrace: SentryId(uuidString: traceId)) result(nil) } + + #if os(iOS) + // Taken from the Flutter engine: + // https://github.com/flutter/engine/blob/main/shell/platform/darwin/ios/framework/Source/vsync_waiter_ios.mm#L150 + private func displayRefreshRate(_ result: @escaping FlutterResult) { + let displayLink = CADisplayLink(target: self, selector: #selector(onDisplayLink(_:))) + displayLink.add(to: .main, forMode: .common) + displayLink.isPaused = true + + let preferredFPS = displayLink.preferredFramesPerSecond + displayLink.invalidate() + + if preferredFPS != 0 { + result(preferredFPS) + return + } + + if #available(iOS 13.0, *) { + guard let windowScene = UIApplication.shared.windows.first?.windowScene else { + result(nil) + return + } + result(windowScene.screen.maximumFramesPerSecond) + } else { + result(UIScreen.main.maximumFramesPerSecond) + } + } + + @objc private func onDisplayLink(_ displayLink: CADisplayLink) { + // No-op + } + #elseif os(macOS) + private func displayRefreshRate(_ result: @escaping FlutterResult) { + // We don't use CADisplayLink for macOS because it's only available starting with macOS 14 + guard let window = NSApplication.shared.keyWindow else { + result(nil) + return + } + + guard let screen = window.screen else { + result(nil) + return + } + + guard let displayID = + screen.deviceDescription[NSDeviceDescriptionKey("NSScreenNumber")] as? CGDirectDisplayID else { + result(nil) + return + } + + guard let mode = CGDisplayCopyDisplayMode(displayID) else { + result(nil) + return + } + + result(Int(mode.refreshRate)) + } + #endif } // swiftlint:enable function_body_length diff --git a/flutter/lib/src/frame_callback_handler.dart b/flutter/lib/src/frame_callback_handler.dart index 71a8f928b1..139d3cbde9 100644 --- a/flutter/lib/src/frame_callback_handler.dart +++ b/flutter/lib/src/frame_callback_handler.dart @@ -1,7 +1,11 @@ +import 'package:flutter/cupertino.dart'; import 'package:flutter/scheduler.dart'; abstract class FrameCallbackHandler { void addPostFrameCallback(FrameCallback callback); + void addPersistentFrameCallback(FrameCallback callback); + Future get endOfFrame; + bool get hasScheduledFrame; } class DefaultFrameCallbackHandler implements FrameCallbackHandler { @@ -12,4 +16,21 @@ class DefaultFrameCallbackHandler implements FrameCallbackHandler { SchedulerBinding.instance.addPostFrameCallback(callback); } catch (_) {} } + + @override + void addPersistentFrameCallback(FrameCallback callback) { + try { + WidgetsBinding.instance.addPersistentFrameCallback(callback); + } catch (_) {} + } + + @override + Future get endOfFrame async { + try { + await WidgetsBinding.instance.endOfFrame; + } catch (_) {} + } + + @override + bool get hasScheduledFrame => WidgetsBinding.instance.hasScheduledFrame; } diff --git a/flutter/lib/src/native/sentry_native_binding.dart b/flutter/lib/src/native/sentry_native_binding.dart index 96962a0575..54223b5561 100644 --- a/flutter/lib/src/native/sentry_native_binding.dart +++ b/flutter/lib/src/native/sentry_native_binding.dart @@ -46,6 +46,8 @@ abstract class SentryNativeBinding { Future discardProfiler(SentryId traceId); + Future displayRefreshRate(); + Future?> collectProfile( SentryId traceId, int startTimeNs, int endTimeNs); diff --git a/flutter/lib/src/native/sentry_native_channel.dart b/flutter/lib/src/native/sentry_native_channel.dart index 2b3e703065..e6888eecac 100644 --- a/flutter/lib/src/native/sentry_native_channel.dart +++ b/flutter/lib/src/native/sentry_native_channel.dart @@ -178,4 +178,8 @@ class SentryNativeChannel .map(DebugImage.fromJson) .toList(); }); + + @override + Future displayRefreshRate() => + _channel.invokeMethod('displayRefreshRate'); } diff --git a/flutter/lib/src/sentry_flutter.dart b/flutter/lib/src/sentry_flutter.dart index f9914d7eaa..8cf3d995ba 100644 --- a/flutter/lib/src/sentry_flutter.dart +++ b/flutter/lib/src/sentry_flutter.dart @@ -3,6 +3,7 @@ import 'dart:ui'; import 'package:flutter/widgets.dart'; import 'package:meta/meta.dart'; +import 'span_frame_metrics_collector.dart'; import '../sentry_flutter.dart'; import 'event_processor/android_platform_exception_event_processor.dart'; import 'event_processor/flutter_exception_event_processor.dart'; @@ -135,6 +136,8 @@ mixin SentryFlutter { options.addEventProcessor(PlatformExceptionEventProcessor()); + options.addPerformanceCollector(SpanFrameMetricsCollector(options)); + _setSdk(options); } diff --git a/flutter/lib/src/sentry_flutter_options.dart b/flutter/lib/src/sentry_flutter_options.dart index ae83de611e..913070e9ca 100644 --- a/flutter/lib/src/sentry_flutter_options.dart +++ b/flutter/lib/src/sentry_flutter_options.dart @@ -232,6 +232,20 @@ class SentryFlutterOptions extends SentryOptions { /// Read timeout. This will only be synced to the Android native SDK. Duration readTimeout = Duration(seconds: 5); + /// Enable or disable Frames Tracking, which is used to report frame information + /// for every [ISentrySpan]. + /// + /// When enabled, the following metrics are reported for each span: + /// - Slow frames: The number of frames that exceeded a specified threshold for frame duration. + /// - Frozen frames: The number of frames that took an unusually long time to render, indicating a potential freeze or hang. + /// - Total frames count: The total number of frames rendered during the span. + /// - Frames delay: The delayed frame render duration of all frames. + + /// Read more about frames tracking here: https://develop.sentry.dev/sdk/performance/frames-delay/ + /// + /// Defaults to `true` + bool enableFramesTracking = true; + /// By using this, you are disabling native [Breadcrumb] tracking and instead /// you are just tracking [Breadcrumb]s which result from events available /// in the current Flutter environment. diff --git a/flutter/lib/src/span_frame_metrics_collector.dart b/flutter/lib/src/span_frame_metrics_collector.dart new file mode 100644 index 0000000000..ecf0ca961c --- /dev/null +++ b/flutter/lib/src/span_frame_metrics_collector.dart @@ -0,0 +1,256 @@ +import 'dart:collection'; +import 'dart:math'; + +import 'package:flutter/cupertino.dart'; +import 'package:meta/meta.dart'; + +import '../sentry_flutter.dart'; + +import 'frame_callback_handler.dart'; +import 'native/sentry_native_binding.dart'; + +@internal +class SpanFrameMetricsCollector implements PerformanceContinuousCollector { + static const _frozenFrameThresholdMs = 700; + static const totalFramesKey = 'frames.total'; + static const framesDelayKey = 'frames.delay'; + static const slowFramesKey = 'frames.slow'; + static const frozenFramesKey = 'frames.frozen'; + + final SentryFlutterOptions options; + final FrameCallbackHandler _frameCallbackHandler; + final SentryNativeBinding? _native; + + final bool _isTestMode; + + /// Stores frame timestamps and their durations in milliseconds. + /// Keys are frame timestamps, values are frame durations. + /// The timestamps mark the end of the frame. + final frames = SplayTreeMap(); + + /// Stores the spans that are actively being tracked. + /// After the frames are calculated and stored in the span the span is removed from this list. + final activeSpans = SplayTreeSet( + (a, b) => a.startTimestamp.compareTo(b.startTimestamp)); + + bool get isTrackingPaused => _isTrackingPaused; + bool _isTrackingPaused = true; + + bool get isTrackingRegistered => _isTrackingRegistered; + bool _isTrackingRegistered = false; + + int displayRefreshRate = 60; + + final _stopwatch = Stopwatch(); + + SpanFrameMetricsCollector(this.options, + {FrameCallbackHandler? frameCallbackHandler, + SentryNativeBinding? native, + @internal bool isTestMode = false}) + : _frameCallbackHandler = + frameCallbackHandler ?? DefaultFrameCallbackHandler(), + _native = native ?? SentryFlutter.native, + _isTestMode = isTestMode; + + @override + Future onSpanStarted(ISentrySpan span) async { + if (span is NoOpSentrySpan || !options.enableFramesTracking) { + return; + } + + final fetchedDisplayRefreshRate = await _native?.displayRefreshRate(); + if (fetchedDisplayRefreshRate != null) { + options.logger(SentryLevel.debug, + 'Retrieved display refresh rate at $fetchedDisplayRefreshRate'); + displayRefreshRate = fetchedDisplayRefreshRate; + } else { + options.logger(SentryLevel.debug, + 'Could not fetch display refresh rate, keeping at 60hz by default'); + } + + activeSpans.add(span); + startFrameTracking(); + } + + @override + Future onSpanFinished(ISentrySpan span, DateTime endTimestamp) async { + if (span is NoOpSentrySpan || !activeSpans.contains(span)) return; + + final frameMetrics = + calculateFrameMetrics(span, endTimestamp, displayRefreshRate); + _applyFrameMetricsToSpan(span, frameMetrics); + + activeSpans.remove(span); + if (activeSpans.isEmpty) { + clear(); + } else { + frames.removeWhere((frameTimestamp, _) => + frameTimestamp.isBefore(activeSpans.first.startTimestamp)); + } + } + + /// Calls [WidgetsBinding.instance.addPersistentFrameCallback] which cannot be unregistered + /// and exists for the duration of the application's lifetime. + /// + /// Stopping the frame tracking means setting [isTrackingPaused] is `true` + /// to prevent actions being done when the frame callback is triggered. + void startFrameTracking() { + _isTrackingPaused = false; + + if (!_isTrackingRegistered) { + _frameCallbackHandler.addPersistentFrameCallback(measureFrameDuration); + _isTrackingRegistered = true; + } + } + + /// Records the duration of a single frame and stores it in [frames]. + /// + /// This method is called for each frame when frame tracking is active. + Future measureFrameDuration(Duration duration) async { + // Using the stopwatch to measure the frame duration is flaky in ci + if (_isTestMode) { + // ignore: invalid_use_of_internal_member + frames[options.clock().add(duration)] = duration.inMilliseconds; + return; + } + + if (_isTrackingPaused) return; + + if (!_stopwatch.isRunning) { + _stopwatch.start(); + } + + await _frameCallbackHandler.endOfFrame; + + final frameDuration = _stopwatch.elapsedMilliseconds; + // ignore: invalid_use_of_internal_member + frames[options.clock()] = frameDuration; + + _stopwatch.reset(); + + if (_frameCallbackHandler.hasScheduledFrame == true) { + _stopwatch.start(); + } + } + + void _applyFrameMetricsToSpan( + ISentrySpan span, Map frameMetrics) { + frameMetrics.forEach((key, value) { + span.setData(key, value); + }); + + // This will call the methods on the tracer, not on the span directly + if (span is SentrySpan && span.isRootSpan) { + frameMetrics.forEach((key, value) { + // ignore: invalid_use_of_internal_member + span.tracer.setData(key, value); + + // In measurements we change e.g frames.total to frames_total + // We don't do span.tracer.setMeasurement because setMeasurement in SentrySpan + // uses the tracer internally + span.setMeasurement(key.replaceAll('.', '_'), value); + }); + } + } + + @visibleForTesting + Map calculateFrameMetrics( + ISentrySpan span, DateTime spanEndTimestamp, int displayRefreshRate) { + if (frames.isEmpty) { + options.logger( + SentryLevel.info, 'No frame durations available in frame tracker.'); + return {}; + } + + final expectedFrameDuration = ((1 / displayRefreshRate) * 1000).toInt(); + + int slowFramesCount = 0; + int frozenFramesCount = 0; + int slowFramesDuration = 0; + int frozenFramesDuration = 0; + int framesDelay = 0; + + for (final entry in frames.entries) { + final frameDuration = entry.value; + final frameEndTimestamp = entry.key; + final frameStartMs = + frameEndTimestamp.millisecondsSinceEpoch - frameDuration; + final frameEndMs = frameEndTimestamp.millisecondsSinceEpoch; + final spanStartMs = span.startTimestamp.millisecondsSinceEpoch; + final spanEndMs = spanEndTimestamp.millisecondsSinceEpoch; + + final frameFullyContainedInSpan = + frameEndMs <= spanEndMs && frameStartMs >= spanStartMs; + final frameStartsBeforeSpan = + frameStartMs < spanStartMs && frameEndMs > spanStartMs; + final frameEndsAfterSpan = + frameStartMs < spanEndMs && frameEndMs > spanEndMs; + final framePartiallyContainedInSpan = + frameStartsBeforeSpan || frameEndsAfterSpan; + + int effectiveDuration = 0; + int effectiveDelay = 0; + + if (frameFullyContainedInSpan) { + effectiveDuration = frameDuration; + effectiveDelay = max(0, frameDuration - expectedFrameDuration); + } else if (framePartiallyContainedInSpan) { + final intersectionStart = max(frameStartMs, spanStartMs); + final intersectionEnd = min(frameEndMs, spanEndMs); + effectiveDuration = intersectionEnd - intersectionStart; + + final fullFrameDelay = max(0, frameDuration - expectedFrameDuration); + final intersectionRatio = effectiveDuration / frameDuration; + effectiveDelay = (fullFrameDelay * intersectionRatio).round(); + } else if (frameStartMs > spanEndMs) { + // Other frames will be newer than this span, as frames are ordered + break; + } else { + // Frame is completely outside the span, skip it + continue; + } + + if (effectiveDuration > _frozenFrameThresholdMs) { + frozenFramesCount++; + frozenFramesDuration += effectiveDuration; + } else if (effectiveDuration > expectedFrameDuration) { + slowFramesCount++; + slowFramesDuration += effectiveDuration; + } + + framesDelay += effectiveDelay; + } + + final spanDuration = + spanEndTimestamp.difference(span.startTimestamp).inMilliseconds; + final totalFramesCount = + ((spanDuration - (slowFramesDuration + frozenFramesDuration)) / + expectedFrameDuration) + + slowFramesCount + + frozenFramesCount; + + if (totalFramesCount < 0 || + framesDelay < 0 || + slowFramesCount < 0 || + frozenFramesCount < 0) { + options.logger(SentryLevel.warning, + 'Negative frame metrics calculated. Dropping frame metrics.'); + return {}; + } + + return { + SpanFrameMetricsCollector.totalFramesKey: totalFramesCount.toInt(), + SpanFrameMetricsCollector.framesDelayKey: framesDelay, + SpanFrameMetricsCollector.slowFramesKey: slowFramesCount, + SpanFrameMetricsCollector.frozenFramesKey: frozenFramesCount, + }; + } + + @override + void clear() { + _isTrackingPaused = true; + frames.clear(); + activeSpans.clear(); + displayRefreshRate = 60; + } +} diff --git a/flutter/test/fake_frame_callback_handler.dart b/flutter/test/fake_frame_callback_handler.dart index 0dc968f22c..aa450a7911 100644 --- a/flutter/test/fake_frame_callback_handler.dart +++ b/flutter/test/fake_frame_callback_handler.dart @@ -1,9 +1,9 @@ import 'package:flutter/scheduler.dart'; import 'package:sentry_flutter/src/frame_callback_handler.dart'; -class FakeFrameCallbackHandler implements FrameCallbackHandler { - FrameCallback? storedCallback; +import 'mocks.dart'; +class FakeFrameCallbackHandler implements FrameCallbackHandler { final Duration finishAfterDuration; FakeFrameCallbackHandler( @@ -15,4 +15,19 @@ class FakeFrameCallbackHandler implements FrameCallbackHandler { await Future.delayed(finishAfterDuration); callback(Duration.zero); } + + @override + Future addPersistentFrameCallback(FrameCallback callback) async { + for (final duration in fakeFrameDurations) { + // Let's wait a bit so the timestamp intervals are large enough + await Future.delayed(Duration(milliseconds: 20)); + callback(duration); + } + } + + @override + bool hasScheduledFrame = true; + + @override + Future get endOfFrame => Future.value(); } diff --git a/flutter/test/mocks.dart b/flutter/test/mocks.dart index 4b7ff1aed5..f5e5cb65ce 100644 --- a/flutter/test/mocks.dart +++ b/flutter/test/mocks.dart @@ -191,3 +191,18 @@ class TestBindingWrapper implements BindingWrapper { } class MockSentryClient with NoSuchMethodProvider implements SentryClient {} + +// All these values are based on the fakeFrameDurations list. +// The expected total frames is also based on the span duration of 1000ms and the slow and frozen frames. +const expectedTotalFrames = 17; +const expectedFramesDelay = 722; +const expectedSlowFrames = 2; +const expectedFrozenFrames = 1; + +final fakeFrameDurations = [ + Duration(milliseconds: 0), + Duration(milliseconds: 10), + Duration(milliseconds: 20), + Duration(milliseconds: 40), + Duration(milliseconds: 710), +]; diff --git a/flutter/test/mocks.mocks.dart b/flutter/test/mocks.mocks.dart index bf6114a638..7e595ab4cf 100644 --- a/flutter/test/mocks.mocks.dart +++ b/flutter/test/mocks.mocks.dart @@ -755,6 +755,21 @@ class MockSentrySpan extends _i1.Mock implements _i3.SentrySpan { _i1.throwOnMissingStub(this); } + @override + bool get isRootSpan => (super.noSuchMethod( + Invocation.getter(#isRootSpan), + returnValue: false, + ) as bool); + + @override + _i4.SentryTracer get tracer => (super.noSuchMethod( + Invocation.getter(#tracer), + returnValue: _FakeSentryTracer_4( + this, + Invocation.getter(#tracer), + ), + ) as _i4.SentryTracer); + @override set status(_i3.SpanStatus? status) => super.noSuchMethod( Invocation.setter( @@ -1270,6 +1285,15 @@ class MockSentryNativeBinding extends _i1.Mock returnValueForMissingStub: _i8.Future.value(), ) as _i8.Future); + @override + _i8.Future displayRefreshRate() => (super.noSuchMethod( + Invocation.method( + #displayRefreshRate, + [], + ), + returnValue: _i8.Future.value(), + ) as _i8.Future); + @override _i8.Future?> collectProfile( _i3.SentryId? traceId, diff --git a/flutter/test/span_frame_metrics_collector_test.dart b/flutter/test/span_frame_metrics_collector_test.dart new file mode 100644 index 0000000000..70c3348070 --- /dev/null +++ b/flutter/test/span_frame_metrics_collector_test.dart @@ -0,0 +1,274 @@ +import 'package:flutter/cupertino.dart'; +import 'package:flutter_test/flutter_test.dart'; +import 'package:mockito/mockito.dart'; +import 'package:sentry_flutter/sentry_flutter.dart'; +import 'package:sentry_flutter/src/span_frame_metrics_collector.dart'; + +import 'fake_frame_callback_handler.dart'; +import 'mocks.dart'; + +// ignore: implementation_imports +import 'package:sentry/src/sentry_tracer.dart'; + +import 'mocks.mocks.dart'; + +void main() { + late Fixture fixture; + + setUp(() { + fixture = Fixture(); + WidgetsFlutterBinding.ensureInitialized(); + + when(fixture.mockSentryNative.displayRefreshRate()) + .thenAnswer((_) async => 60); + }); + + test('clear() clears frames, running spans and pauses frame tracking', () { + final sut = fixture.sut; + sut.frames[DateTime.now()] = 1; + final mockSpan = MockSentrySpan(); + when(mockSpan.startTimestamp).thenReturn(DateTime.now()); + + sut.onSpanStarted(mockSpan); + sut.clear(); + + expect(sut.frames, isEmpty); + expect(sut.activeSpans, isEmpty); + expect(sut.isTrackingPaused, isTrue); + }); + + test('does not start frame tracking if frames tracking is disabled', () { + final sut = fixture.sut; + fixture.options.enableFramesTracking = false; + + final span = MockSentrySpan(); + sut.onSpanStarted(span); + + expect(sut.isTrackingRegistered, isFalse); + }); + + test( + 'captures metrics with display refresh rate of 60 if native refresh rate is null', + () async { + final sut = fixture.sut; + fixture.options.tracesSampleRate = 1.0; + fixture.options.addPerformanceCollector(sut); + final startTimestamp = DateTime.now(); + final endTimestamp = + startTimestamp.add(Duration(milliseconds: 1000)).toUtc(); + + when(fixture.mockSentryNative.displayRefreshRate()) + .thenAnswer((_) async => null); + + final tracer = SentryTracer( + SentryTransactionContext('name', 'op', description: 'tracerDesc'), + fixture.hub, + startTimestamp: startTimestamp); + + await Future.delayed(Duration(milliseconds: 500)); + await tracer.finish(endTimestamp: endTimestamp); + + expect(tracer.data['frames.slow'], expectedSlowFrames); + expect(tracer.data['frames.frozen'], expectedFrozenFrames); + expect(tracer.data['frames.delay'], expectedFramesDelay); + expect(tracer.data['frames.total'], expectedTotalFrames); + }); + + test('onSpanFinished removes frames older than span start timestamp', + () async { + // Using multiple spans to test frame removal. When the last span is finished, + // the tracker clears all data, so we need at least two spans to observe partial removal. + final sut = fixture.sut; + final span1 = MockSentrySpan(); + final span2 = MockSentrySpan(); + final spanStartTimestamp = DateTime.now(); + final spanEndTimestamp = spanStartTimestamp.add(Duration(seconds: 1)); + + when(span1.isRootSpan).thenReturn(false); + when(span1.startTimestamp).thenReturn(spanStartTimestamp); + when(span1.context).thenReturn(SentrySpanContext(operation: 'op')); + + when(span2.isRootSpan).thenReturn(false); + when(span2.startTimestamp) + .thenReturn(spanStartTimestamp.add(Duration(seconds: 2))); + when(span2.context).thenReturn(SentrySpanContext(operation: 'op')); + + sut.activeSpans.add(span1); + sut.activeSpans.add(span2); + + sut.frames[spanStartTimestamp.subtract(Duration(seconds: 5))] = 1; + sut.frames[spanStartTimestamp.subtract(Duration(seconds: 3))] = 1; + sut.frames[spanStartTimestamp.add(Duration(seconds: 4))] = 1; + + await sut.onSpanFinished(span1, spanEndTimestamp); + + expect(sut.frames, hasLength(1)); + expect(sut.frames.keys.first, spanStartTimestamp.add(Duration(seconds: 4))); + }); + + test( + 'starting and finishing a span calculates and attaches frame metrics to span', + () async { + final sut = fixture.sut; + fixture.options.tracesSampleRate = 1.0; + fixture.options.addPerformanceCollector(sut); + final startTimestamp = DateTime.now(); + final endTimestamp = startTimestamp.add(Duration(milliseconds: 1000)); + + final tracer = SentryTracer( + SentryTransactionContext('name1', 'op1'), fixture.hub, + startTimestamp: startTimestamp); + + await Future.delayed(Duration(milliseconds: 500)); + await tracer.finish(endTimestamp: endTimestamp); + + expect(tracer.data['frames.slow'], expectedSlowFrames); + expect(tracer.data['frames.frozen'], expectedFrozenFrames); + expect(tracer.data['frames.delay'], expectedFramesDelay); + expect(tracer.data['frames.total'], expectedTotalFrames); + + expect(tracer.measurements['frames_delay']!.value, expectedFramesDelay); + expect(tracer.measurements['frames_total']!.value, expectedTotalFrames); + expect(tracer.measurements['frames_slow']!.value, expectedSlowFrames); + expect(tracer.measurements['frames_frozen']!.value, expectedFrozenFrames); + }); + + test('frame fully contained in span should contribute to frame metrics', () { + final sut = fixture.sut; + final span = MockSentrySpan(); + + final now = DateTime.now(); + when(span.startTimestamp).thenReturn(now); + when(span.endTimestamp).thenReturn(now.add(Duration(milliseconds: 500))); + sut.frames[now.add(Duration(milliseconds: 200))] = 100; + + final metrics = sut.calculateFrameMetrics(span, span.endTimestamp!, 60); + + expect(metrics['frames.total'], 26); + expect(metrics['frames.slow'], 1); + expect(metrics['frames.delay'], 84); + expect(metrics['frames.frozen'], 0); + }); + + test('frame fully outside of span should not contribute to frame metrics', + () { + final sut = fixture.sut; + final span = MockSentrySpan(); + + final now = DateTime.now(); + when(span.startTimestamp).thenReturn(now); + when(span.endTimestamp).thenReturn(now.add(Duration(milliseconds: 500))); + sut.frames[now.subtract(Duration(milliseconds: 200))] = 100; + + final metrics = sut.calculateFrameMetrics(span, span.endTimestamp!, 60); + + expect(metrics['frames.total'], 31); + expect(metrics['frames.slow'], 0); + expect(metrics['frames.delay'], 0); + expect(metrics['frames.frozen'], 0); + }); + + test( + 'frame partially contained in span (starts before span and ends within span) should contribute to frame metrics', + () { + final sut = fixture.sut; + final span = MockSentrySpan(); + + final now = DateTime.now(); + when(span.startTimestamp).thenReturn(now); + when(span.endTimestamp).thenReturn(now.add(Duration(milliseconds: 500))); + // 50ms before span starts and ends 50ms after span starts + sut.frames[now.add(Duration(milliseconds: 50))] = 100; + + final metrics = sut.calculateFrameMetrics(span, span.endTimestamp!, 60); + + expect(metrics['frames.total'], 29); + expect(metrics['frames.slow'], 1); + expect(metrics['frames.delay'], 42); + expect(metrics['frames.frozen'], 0); + }); + + test( + 'frame partially contained in span (starts withing span and ends after span end) should contribute to frame metrics', + () { + final sut = fixture.sut; + final span = MockSentrySpan(); + + final now = DateTime.now(); + when(span.startTimestamp).thenReturn(now); + when(span.endTimestamp).thenReturn(now.add(Duration(milliseconds: 500))); + sut.frames[now.add(Duration(milliseconds: 550))] = 100; + + final metrics = sut.calculateFrameMetrics(span, span.endTimestamp!, 60); + + expect(metrics['frames.total'], 29); + expect(metrics['frames.slow'], 1); + expect(metrics['frames.delay'], 42); + expect(metrics['frames.frozen'], 0); + }); + + test('calculates frame metrics correctly for multiple simultaneous spans', + () async { + final sut = fixture.sut; + fixture.options.tracesSampleRate = 1.0; + fixture.options.addPerformanceCollector(sut); + final startTimestamp = DateTime.now(); + final endTimestamp = startTimestamp.add(Duration(milliseconds: 1000)); + + final tracer = SentryTracer( + SentryTransactionContext('name1', 'op1'), fixture.hub, + startTimestamp: startTimestamp); + + final child = tracer.startChild('child', + startTimestamp: startTimestamp.add(Duration(milliseconds: 1))) + as SentrySpan; + + await Future.delayed(Duration(milliseconds: 500)); + await child.finish(endTimestamp: endTimestamp); + + await Future.delayed(Duration(milliseconds: 500)); + await tracer.finish(endTimestamp: endTimestamp); + + expect(child.data['frames.slow'], expectedSlowFrames); + expect(child.data['frames.frozen'], expectedFrozenFrames); + expect(child.data['frames.delay'], expectedFramesDelay); + expect(child.data['frames.total'], expectedTotalFrames); + + // total frames is hardcoded here since it depends on span duration as well + // and we are deviating from the default 800ms to 1600ms for the whole transaction + expect(tracer.data['frames.slow'], expectedSlowFrames); + expect(tracer.data['frames.frozen'], expectedFrozenFrames); + expect(tracer.data['frames.delay'], expectedFramesDelay); + // expect(tracer.data['frames.total'], 54); + expect(tracer.measurements['frames_delay']!.value, expectedFramesDelay); + // expect(tracer.measurements['frames_total']!.value, 54); + expect(tracer.measurements['frames_slow']!.value, expectedSlowFrames); + expect(tracer.measurements['frames_frozen']!.value, expectedFrozenFrames); + }); + + test('frame tracker is paused after finishing a span', () async { + final sut = fixture.sut; + fixture.options.tracesSampleRate = 1.0; + fixture.options.addPerformanceCollector(sut); + + final tracer = + SentryTracer(SentryTransactionContext('name', 'op'), fixture.hub); + + await Future.delayed(Duration(milliseconds: 100)); + await tracer.finish(); + + expect(sut.isTrackingPaused, isTrue); + }); +} + +class Fixture { + final options = SentryFlutterOptions(dsn: fakeDsn); + late final hub = Hub(options); + final fakeFrameCallbackHandler = FakeFrameCallbackHandler(); + final mockSentryNative = MockSentryNativeBinding(); + + SpanFrameMetricsCollector get sut => SpanFrameMetricsCollector(options, + frameCallbackHandler: fakeFrameCallbackHandler, + native: mockSentryNative, + isTestMode: true); +}