Skip to content

Commit

Permalink
Update implementation
Browse files Browse the repository at this point in the history
  • Loading branch information
buenaflor committed Jun 24, 2024
1 parent b5630cb commit 71cdcdb
Show file tree
Hide file tree
Showing 3 changed files with 140 additions and 60 deletions.
95 changes: 61 additions & 34 deletions flutter/lib/src/span_frame_metrics_collector.dart
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
import 'dart:collection';
import 'dart:math';

import 'package:flutter/cupertino.dart';
import 'package:meta/meta.dart';
Expand All @@ -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<DateTime, int>();
/// The timestamps mark the end of the frame.
final frames = SplayTreeMap<DateTime, int>();

/// 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.
Expand All @@ -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,
Expand All @@ -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');
}

Expand All @@ -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));
}
}

Expand All @@ -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<void> 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;
}

Expand All @@ -122,7 +124,7 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector {

final frameDuration = _stopwatch.elapsedMilliseconds;

Check warning on line 125 in flutter/lib/src/span_frame_metrics_collector.dart

View check run for this annotation

Codecov / codecov/patch

flutter/lib/src/span_frame_metrics_collector.dart#L125

Added line #L125 was not covered by tests
// ignore: invalid_use_of_internal_member
frameDurations[options.clock()] = frameDuration;
frames[options.clock()] = frameDuration;

Check warning on line 127 in flutter/lib/src/span_frame_metrics_collector.dart

View check run for this annotation

Codecov / codecov/patch

flutter/lib/src/span_frame_metrics_collector.dart#L127

Added line #L127 was not covered by tests

_stopwatch.reset();

Check warning on line 129 in flutter/lib/src/span_frame_metrics_collector.dart

View check run for this annotation

Codecov / codecov/patch

flutter/lib/src/span_frame_metrics_collector.dart#L129

Added line #L129 was not covered by tests

Expand All @@ -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
Expand All @@ -154,45 +155,71 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector {

@visibleForTesting
Map<String, int> 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(

Check warning on line 160 in flutter/lib/src/span_frame_metrics_collector.dart

View check run for this annotation

Codecov / codecov/patch

flutter/lib/src/span_frame_metrics_collector.dart#L160

Added line #L160 was not covered by tests
SentryLevel.info, 'No frame durations available in frame tracker.');
return {};

Check warning on line 162 in flutter/lib/src/span_frame_metrics_collector.dart

View check run for this annotation

Codecov / codecov/patch

flutter/lib/src/span_frame_metrics_collector.dart#L162

Added line #L162 was not covered by tests
}

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) +
Expand All @@ -219,7 +246,7 @@ class SpanFrameMetricsCollector implements PerformanceContinuousCollector {
@override
void clear() {
_isTrackingPaused = true;
frameDurations.clear();
frames.clear();
activeSpans.clear();
displayRefreshRate = 60;
}
Expand Down
4 changes: 2 additions & 2 deletions flutter/test/mocks.dart
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
101 changes: 77 additions & 24 deletions flutter/test/span_frame_metrics_collector_test.dart
Original file line number Diff line number Diff line change
Expand Up @@ -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);
});
Expand All @@ -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);
Expand Down Expand Up @@ -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(
Expand All @@ -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,
Expand All @@ -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',
Expand All @@ -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,
Expand Down

0 comments on commit 71cdcdb

Please sign in to comment.