firka/flutter
firka/flutter
5
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Add "Frame Request Pending" lag to collected metrics (#135279)

Browse Source 
This measures the wall clock time between a new frame being scheduled in dart code to the Vsync callback in the engine

It's an important source of lag which isn't shown in the top-level UI / Build time graphs, and can correlate with "invisible" missed/non-scheduled frames

I had to change a few unrelated timings in the test, it was only passing based on luck of sort order, and broke when I added more entries to the timeline.

Part of #129150
This commit is contained in:
Callum Moffat 2023-09-25 20:35:57 -04:00 committed by GitHub
parent d28c10ceb2
commit b097d24022
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 117 additions and 6 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

64
packages/flutter_driver/lib/src/driver/frame_request_pending_latency_summarizer.dart Normal file
View File

@ -0,0 +1,64 @@
// Copyright 2014 The Flutter Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
import 'percentile_utils.dart';
import 'timeline.dart';
/// Event name for frame request pending timeline events.
const String kFrameRequestPendingEvent = 'Frame Request Pending';
/// Summarizes [TimelineEvents]s corresponding to [kFrameRequestPendingEvent] events.
///
/// `FrameRequestPendingLatency` is the time between `Animator::RequestFrame`
/// and `Animator::BeginFrame` for each frame built by the Flutter engine.
class FrameRequestPendingLatencySummarizer {
/// Creates a FrameRequestPendingLatencySummarizer given the timeline events.
FrameRequestPendingLatencySummarizer(this.frameRequestPendingEvents);
/// Timeline events with names in [kFrameRequestPendingTimelineEventNames].
final List<TimelineEvent> frameRequestPendingEvents;
/// Computes the average `FrameRequestPendingLatency` over the period of the timeline.
double computeAverageFrameRequestPendingLatency() {
final List<double> frameRequestPendingLatencies =
_computeFrameRequestPendingLatencies();
if (frameRequestPendingLatencies.isEmpty) {
return 0;
}
final double total = frameRequestPendingLatencies.reduce((double a, double b) => a + b);
return total / frameRequestPendingLatencies.length;
}
/// Computes the [percentile]-th percentile `FrameRequestPendingLatency` over the
/// period of the timeline.
double computePercentileFrameRequestPendingLatency(double percentile) {
final List<double> frameRequestPendingLatencies =
_computeFrameRequestPendingLatencies();
if (frameRequestPendingLatencies.isEmpty) {
return 0;
}
return findPercentile(frameRequestPendingLatencies, percentile);
}
List<double> _computeFrameRequestPendingLatencies() {
final List<double> result = <double>[];
final Map<String, int> starts = <String, int>{};
for (int i = 0; i < frameRequestPendingEvents.length; i++) {
final TimelineEvent event = frameRequestPendingEvents[i];
if (event.phase == 'b') {
final String? id = event.json['id'] as String?;
if (id != null) {
starts[id] = event.timestampMicros!;
}
} else if (event.phase == 'e') {
final int? start = starts[event.json['id']];
if (start != null) {
result.add((event.timestampMicros! - start).toDouble());
}
}
}
return result;
}
}

15
packages/flutter_driver/lib/src/driver/timeline_summary.dart
View File

@ -9,6 +9,7 @@ import 'package:file/file.dart';
import 'package:path/path.dart' as path;
import 'common.dart';
import 'frame_request_pending_latency_summarizer.dart';
import 'gc_summarizer.dart';
import 'percentile_utils.dart';
import 'profiling_summarizer.dart';
@ -258,6 +259,14 @@ class TimelineSummary {
/// * "worst_picture_cache_memory": The worst (highest) value seen for the
/// memory used for the engine picture cache entries.
/// See [RasterCacheSummarizer.computeWorstPictureMemory].
/// * "average_frame_request_pending_latency": Computes the average of the delay
/// between `Animator::RequestFrame` and `Animator::BeginFrame` in the engine.
/// See [FrameRequestPendingLatencySummarizer.computeAverageFrameRequestPendingLatency].
/// * "90th_percentile_frame_request_pending_latency" and
/// "99th_percentile_frame_request_pending_latency": The 90/99-th percentile
/// delay between `Animator::RequestFrame` and `Animator::BeginFrame` in the
/// engine.
/// See [FrameRequestPendingLatencySummarizer.computePercentileFrameRequestPendingLatency].
Map<String, dynamic> get summaryJson {
final SceneDisplayLagSummarizer sceneDisplayLagSummarizer = _sceneDisplayLagSummarizer();
final VsyncFrameLagSummarizer vsyncFrameLagSummarizer = _vsyncFrameLagSummarizer();
@ -265,6 +274,7 @@ class TimelineSummary {
final RasterCacheSummarizer rasterCacheSummarizer = _rasterCacheSummarizer();
final GCSummarizer gcSummarizer = _gcSummarizer();
final RefreshRateSummary refreshRateSummary = RefreshRateSummary(vsyncEvents: _extractNamedEvents(kUIThreadVsyncProcessEvent));
final FrameRequestPendingLatencySummarizer frameRequestPendingLatencySummarizer = _frameRequestPendingLatencySummarizer();
final Map<String, dynamic> timelineSummary = <String, dynamic>{
'average_frame_build_time_millis': computeAverageFrameBuildTimeMillis(),
@ -303,6 +313,9 @@ class TimelineSummary {
'average_layer_cache_count': rasterCacheSummarizer.computeAverageLayerCount(),
'90th_percentile_layer_cache_count': rasterCacheSummarizer.computePercentileLayerCount(90.0),
'99th_percentile_layer_cache_count': rasterCacheSummarizer.computePercentileLayerCount(99.0),
'average_frame_request_pending_latency': frameRequestPendingLatencySummarizer.computeAverageFrameRequestPendingLatency(),
'90th_percentile_frame_request_pending_latency': frameRequestPendingLatencySummarizer.computePercentileFrameRequestPendingLatency(90.0),
'99th_percentile_frame_request_pending_latency': frameRequestPendingLatencySummarizer.computePercentileFrameRequestPendingLatency(99.0),
'worst_layer_cache_count': rasterCacheSummarizer.computeWorstLayerCount(),
'average_layer_cache_memory': rasterCacheSummarizer.computeAverageLayerMemory(),
'90th_percentile_layer_cache_memory': rasterCacheSummarizer.computePercentileLayerMemory(90.0),
@ -491,5 +504,7 @@ class TimelineSummary {
RasterCacheSummarizer _rasterCacheSummarizer() => RasterCacheSummarizer(_extractNamedEvents(kRasterCacheEvent));
FrameRequestPendingLatencySummarizer _frameRequestPendingLatencySummarizer() => FrameRequestPendingLatencySummarizer(_extractNamedEvents(kFrameRequestPendingEvent));
GCSummarizer _gcSummarizer() => GCSummarizer.fromEvents(_extractEventsWithNames(kGCRootEvents));
}

44
packages/flutter_driver/test/src/real_tests/timeline_summary_test.dart
View File

@ -143,6 +143,20 @@ void main() {
return result;
}
Map<String, dynamic> frameRequestPendingStart(String id, int timeStamp) => <String, dynamic>{
'name': 'Frame Request Pending',
'ph': 'b',
'id': id,
'ts': timeStamp,
};
Map<String, dynamic> frameRequestPendingEnd(String id, int timeStamp) => <String, dynamic>{
'name': 'Frame Request Pending',
'ph': 'e',
'id': id,
'ts': timeStamp,
};
group('frame_count', () {
test('counts frames', () {
expect(
@ -448,13 +462,19 @@ void main() {
expect(
summarize(<Map<String, dynamic>>[
begin(1000), end(19000),
begin(19000), end(29000),
begin(29000), end(49000),
begin(19001), end(29001),
begin(29002), end(49002),
...newGenGC(4, 10, 100),
...oldGenGC(5, 10000, 100),
frameBegin(1000), frameEnd(18000),
frameBegin(19000), frameEnd(28000),
frameBegin(29000), frameEnd(48000),
frameRequestPendingStart('1', 1000),
frameRequestPendingEnd('1', 2000),
frameRequestPendingStart('2', 3000),
frameRequestPendingEnd('2', 5000),
frameRequestPendingStart('3', 6000),
frameRequestPendingEnd('3', 9000),
]).summaryJson,
<String, dynamic>{
'average_frame_build_time_millis': 15.0,
@ -475,7 +495,7 @@ void main() {
'frame_build_times': <int>[17000, 9000, 19000],
'frame_rasterizer_times': <int>[18000, 10000, 20000],
'frame_begin_times': <int>[0, 18000, 28000],
'frame_rasterizer_begin_times': <int>[0, 18000, 28000],
'frame_rasterizer_begin_times': <int>[0, 18001, 28002],
'average_vsync_transitions_missed': 0.0,
'90th_percentile_vsync_transitions_missed': 0.0,
'99th_percentile_vsync_transitions_missed': 0.0,
@ -505,6 +525,9 @@ void main() {
'90hz_frame_percentage': 0,
'120hz_frame_percentage': 0,
'illegal_refresh_rate_frame_count': 0,
'average_frame_request_pending_latency': 2000.0,
'90th_percentile_frame_request_pending_latency': 3000.0,
'99th_percentile_frame_request_pending_latency': 3000.0,
},
);
});
@ -556,8 +579,8 @@ void main() {
test('writes summary to JSON file', () async {
await summarize(<Map<String, dynamic>>[
begin(1000), end(19000),
begin(19000), end(29000),
begin(29000), end(49000),
begin(19001), end(29001),
begin(29002), end(49002),
frameBegin(1000), frameEnd(18000),
frameBegin(19000), frameEnd(28000),
frameBegin(29000), frameEnd(48000),
@ -569,6 +592,12 @@ void main() {
cpuUsage(5000, 20), cpuUsage(5010, 60),
memoryUsage(6000, 20, 40), memoryUsage(6100, 30, 45),
platformVsync(7000), vsyncCallback(7500),
frameRequestPendingStart('1', 1000),
frameRequestPendingEnd('1', 2000),
frameRequestPendingStart('2', 3000),
frameRequestPendingEnd('2', 5000),
frameRequestPendingStart('3', 6000),
frameRequestPendingEnd('3', 9000),
]).writeTimelineToFile('test', destinationDirectory: tempDir.path);
final String written =
await fs.file(path.join(tempDir.path, 'test.timeline_summary.json')).readAsString();
@ -591,7 +620,7 @@ void main() {
'frame_build_times': <int>[17000, 9000, 19000],
'frame_rasterizer_times': <int>[18000, 10000, 20000],
'frame_begin_times': <int>[0, 18000, 28000],
'frame_rasterizer_begin_times': <int>[0, 18000, 28000],
'frame_rasterizer_begin_times': <int>[0, 18001, 28002],
'average_vsync_transitions_missed': 8.0,
'90th_percentile_vsync_transitions_missed': 12.0,
'99th_percentile_vsync_transitions_missed': 12.0,
@ -627,6 +656,9 @@ void main() {
'90hz_frame_percentage': 0,
'120hz_frame_percentage': 0,
'illegal_refresh_rate_frame_count': 0,
'average_frame_request_pending_latency': 2000.0,
'90th_percentile_frame_request_pending_latency': 3000.0,
'99th_percentile_frame_request_pending_latency': 3000.0,
});
});
});