diff --git a/packages/flutter_driver/lib/src/driver/frame_request_pending_latency_summarizer.dart b/packages/flutter_driver/lib/src/driver/frame_request_pending_latency_summarizer.dart new file mode 100644 index 0000000000..2554611103 --- /dev/null +++ b/packages/flutter_driver/lib/src/driver/frame_request_pending_latency_summarizer.dart @@ -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 frameRequestPendingEvents; + + /// Computes the average `FrameRequestPendingLatency` over the period of the timeline. + double computeAverageFrameRequestPendingLatency() { + final List 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 frameRequestPendingLatencies = + _computeFrameRequestPendingLatencies(); + if (frameRequestPendingLatencies.isEmpty) { + return 0; + } + return findPercentile(frameRequestPendingLatencies, percentile); + } + + List _computeFrameRequestPendingLatencies() { + final List result = []; + final Map starts = {}; + 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; + } +} diff --git a/packages/flutter_driver/lib/src/driver/timeline_summary.dart b/packages/flutter_driver/lib/src/driver/timeline_summary.dart index 6d580bd551..d79caeffd0 100644 --- a/packages/flutter_driver/lib/src/driver/timeline_summary.dart +++ b/packages/flutter_driver/lib/src/driver/timeline_summary.dart @@ -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 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 timelineSummary = { '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)); } diff --git a/packages/flutter_driver/test/src/real_tests/timeline_summary_test.dart b/packages/flutter_driver/test/src/real_tests/timeline_summary_test.dart index 430df503df..2e6c70a064 100644 --- a/packages/flutter_driver/test/src/real_tests/timeline_summary_test.dart +++ b/packages/flutter_driver/test/src/real_tests/timeline_summary_test.dart @@ -143,6 +143,20 @@ void main() { return result; } + Map frameRequestPendingStart(String id, int timeStamp) => { + 'name': 'Frame Request Pending', + 'ph': 'b', + 'id': id, + 'ts': timeStamp, + }; + + Map frameRequestPendingEnd(String id, int timeStamp) => { + '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(>[ 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, { 'average_frame_build_time_millis': 15.0, @@ -475,7 +495,7 @@ void main() { 'frame_build_times': [17000, 9000, 19000], 'frame_rasterizer_times': [18000, 10000, 20000], 'frame_begin_times': [0, 18000, 28000], - 'frame_rasterizer_begin_times': [0, 18000, 28000], + 'frame_rasterizer_begin_times': [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(>[ 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': [17000, 9000, 19000], 'frame_rasterizer_times': [18000, 10000, 20000], 'frame_begin_times': [0, 18000, 28000], - 'frame_rasterizer_begin_times': [0, 18000, 28000], + 'frame_rasterizer_begin_times': [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, }); }); });