From 71cdcdb1521c0c922a4d5eb6e3bd1bad8f1f01f7 Mon Sep 17 00:00:00 2001 From: GIancarlo Buenaflor Date: Mon, 24 Jun 2024 15:48:40 +0200 Subject: [PATCH] Update implementation --- .../lib/src/span_frame_metrics_collector.dart | 95 ++++++++++------ flutter/test/mocks.dart | 4 +- .../span_frame_metrics_collector_test.dart | 101 +++++++++++++----- 3 files changed, 140 insertions(+), 60 deletions(-) diff --git a/flutter/lib/src/span_frame_metrics_collector.dart b/flutter/lib/src/span_frame_metrics_collector.dart index 8b45cf3a88..b3873cad73 100644 --- a/flutter/lib/src/span_frame_metrics_collector.dart +++ b/flutter/lib/src/span_frame_metrics_collector.dart @@ -1,4 +1,5 @@ import 'dart:collection'; +import 'dart:math'; import 'package:flutter/cupertino.dart'; import 'package:meta/meta.dart'; @@ -24,7 +25,8 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector { /// Stores frame timestamps and their durations in milliseconds. /// Keys are frame timestamps, values are frame durations. - final frameDurations = SplayTreeMap(); + /// 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. @@ -44,7 +46,7 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector { SpanFrameMetricsCollector(this.options, {FrameCallbackHandler? frameCallbackHandler, SentryNativeBinding? native, - bool isTestMode = false}) + @internal bool isTestMode = false}) : _frameCallbackHandler = frameCallbackHandler ?? DefaultFrameCallbackHandler(), _native = native ?? SentryFlutter.native, @@ -58,11 +60,11 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector { final fetchedDisplayRefreshRate = await _native?.displayRefreshRate(); if (fetchedDisplayRefreshRate != null) { - options.logger(SentryLevel.info, + options.logger(SentryLevel.debug, 'Retrieved display refresh rate at $fetchedDisplayRefreshRate'); displayRefreshRate = fetchedDisplayRefreshRate; } else { - options.logger(SentryLevel.info, + options.logger(SentryLevel.debug, 'Could not fetch display refresh rate, keeping at 60hz by default'); } @@ -82,8 +84,8 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector { if (activeSpans.isEmpty) { clear(); } else { - frameDurations.removeWhere( - (key, _) => key.isBefore(activeSpans.first.startTimestamp)); + frames.removeWhere((frameTimestamp, _) => + frameTimestamp.isBefore(activeSpans.first.startTimestamp)); } } @@ -101,14 +103,14 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector { } } - /// Records the duration of a single frame and stores it in [frameDurations]. + /// 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 - frameDurations[options.clock()] = duration.inMilliseconds; + frames[options.clock().add(duration)] = duration.inMilliseconds; return; } @@ -122,7 +124,7 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector { final frameDuration = _stopwatch.elapsedMilliseconds; // ignore: invalid_use_of_internal_member - frameDurations[options.clock()] = frameDuration; + frames[options.clock()] = frameDuration; _stopwatch.reset(); @@ -142,8 +144,7 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector { frameMetrics.forEach((key, value) { // ignore: invalid_use_of_internal_member span.tracer.setData(key, value); - }); - frameMetrics.forEach((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 @@ -154,45 +155,71 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector { @visibleForTesting Map calculateFrameMetrics( - ISentrySpan span, DateTime endTimestamp, int displayRefreshRate) { - final expectedFrameDuration = ((1 / displayRefreshRate) * 1000).toInt(); - - // Filter frame durations within the span's time range - final timestamps = frameDurations.keys - .takeWhile((value) => - value.isBefore(endTimestamp) && value.isAfter(span.startTimestamp)) - .toList(); - - if (timestamps.isEmpty) { + 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 timestamp in timestamps) { - final frameDuration = frameDurations[timestamp] ?? 0; - - if (frameDuration > _frozenFrameThresholdMs) { - frozenFramesCount += 1; - frozenFramesDuration += frameDuration; - } else if (frameDuration > expectedFrameDuration) { - slowFramesCount += 1; - slowFramesDuration += frameDuration; + 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 { + // Frame is completely outside the span, skip it + continue; } - if (frameDuration > expectedFrameDuration) { - framesDelay += frameDuration - expectedFrameDuration; + if (effectiveDuration > _frozenFrameThresholdMs) { + frozenFramesCount++; + frozenFramesDuration += effectiveDuration; + } else if (effectiveDuration > expectedFrameDuration) { + slowFramesCount++; + slowFramesDuration += effectiveDuration; } + + framesDelay += effectiveDelay; } final spanDuration = - endTimestamp.difference(span.startTimestamp).inMilliseconds; + spanEndTimestamp.difference(span.startTimestamp).inMilliseconds; final totalFramesCount = ((spanDuration - (slowFramesDuration + frozenFramesDuration)) / expectedFrameDuration) + @@ -219,7 +246,7 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector { @override void clear() { _isTrackingPaused = true; - frameDurations.clear(); + frames.clear(); activeSpans.clear(); displayRefreshRate = 60; } diff --git a/flutter/test/mocks.dart b/flutter/test/mocks.dart index 10a69ed9c9..f5e5cb65ce 100644 --- a/flutter/test/mocks.dart +++ b/flutter/test/mocks.dart @@ -193,8 +193,8 @@ 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 800 and the slow and frozen frames. -const expectedTotalFrames = 4; +// 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; diff --git a/flutter/test/span_frame_metrics_collector_test.dart b/flutter/test/span_frame_metrics_collector_test.dart index d81fb80c67..70c3348070 100644 --- a/flutter/test/span_frame_metrics_collector_test.dart +++ b/flutter/test/span_frame_metrics_collector_test.dart @@ -25,14 +25,14 @@ void main() { test('clear() clears frames, running spans and pauses frame tracking', () { final sut = fixture.sut; - sut.frameDurations[DateTime.now()] = 1; + sut.frames[DateTime.now()] = 1; final mockSpan = MockSentrySpan(); when(mockSpan.startTimestamp).thenReturn(DateTime.now()); sut.onSpanStarted(mockSpan); sut.clear(); - expect(sut.frameDurations, isEmpty); + expect(sut.frames, isEmpty); expect(sut.activeSpans, isEmpty); expect(sut.isTrackingPaused, isTrue); }); @@ -53,9 +53,9 @@ void main() { final sut = fixture.sut; fixture.options.tracesSampleRate = 1.0; fixture.options.addPerformanceCollector(sut); - final startTimestamp = DateTime.now().toUtc(); + final startTimestamp = DateTime.now(); final endTimestamp = - startTimestamp.add(Duration(milliseconds: 800)).toUtc(); + startTimestamp.add(Duration(milliseconds: 1000)).toUtc(); when(fixture.mockSentryNative.displayRefreshRate()) .thenAnswer((_) async => null); @@ -96,15 +96,14 @@ void main() { sut.activeSpans.add(span1); sut.activeSpans.add(span2); - sut.frameDurations[spanStartTimestamp.subtract(Duration(seconds: 5))] = 1; - sut.frameDurations[spanStartTimestamp.subtract(Duration(seconds: 3))] = 1; - sut.frameDurations[spanStartTimestamp.add(Duration(seconds: 4))] = 1; + 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.frameDurations, hasLength(1)); - expect(sut.frameDurations.keys.first, - spanStartTimestamp.add(Duration(seconds: 4))); + expect(sut.frames, hasLength(1)); + expect(sut.frames.keys.first, spanStartTimestamp.add(Duration(seconds: 4))); }); test( @@ -114,7 +113,7 @@ void main() { fixture.options.tracesSampleRate = 1.0; fixture.options.addPerformanceCollector(sut); final startTimestamp = DateTime.now(); - final endTimestamp = startTimestamp.add(Duration(milliseconds: 800)); + final endTimestamp = startTimestamp.add(Duration(milliseconds: 1000)); final tracer = SentryTracer( SentryTransactionContext('name1', 'op1'), fixture.hub, @@ -134,24 +133,78 @@ void main() { expect(tracer.measurements['frames_frozen']!.value, expectedFrozenFrames); }); - test('negative values in frame metrics leads to empty map', () async { + test('frame fully contained in span should contribute to frame metrics', () { final sut = fixture.sut; - fixture.options.tracesSampleRate = 1.0; - fixture.options.addPerformanceCollector(sut); - const displayRefreshRate = 60; + final span = MockSentrySpan(); - final tracer = MockSentryTracer(); + 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 startTimestamp = DateTime.now(); - when(tracer.startTimestamp).thenReturn(startTimestamp); - when(tracer.context).thenReturn(SentryTransactionContext('name', 'op')); + 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(); - sut.frameDurations[startTimestamp.add(Duration(milliseconds: 1))] = 500; + 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 frameMetrics = sut.calculateFrameMetrics(tracer, - startTimestamp.add(Duration(milliseconds: 10)), displayRefreshRate); + final metrics = sut.calculateFrameMetrics(span, span.endTimestamp!, 60); - expect(frameMetrics.isEmpty, isTrue); + 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', @@ -160,7 +213,7 @@ void main() { fixture.options.tracesSampleRate = 1.0; fixture.options.addPerformanceCollector(sut); final startTimestamp = DateTime.now(); - final endTimestamp = startTimestamp.add(Duration(milliseconds: 800)); + final endTimestamp = startTimestamp.add(Duration(milliseconds: 1000)); final tracer = SentryTracer( SentryTransactionContext('name1', 'op1'), fixture.hub,