Skip to content
This repository was archived by the owner on Feb 25, 2025. It is now read-only.

Commit 409a5e5

Browse files
CareFCareF
authored
FrameTiming build start timestamp fix and add vsync start timestamp (#20229)
1 parent 18d286a commit 409a5e5

File tree

11 files changed

+125
-32
lines changed

11 files changed

+125
-32
lines changed

‎common/settings.h

Lines changed: 11 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -22,10 +22,17 @@ namespace flutter {
2222

2323
class FrameTiming {
2424
public:
25-
enum Phase { kBuildStart, kBuildFinish, kRasterStart, kRasterFinish, kCount };
26-
27-
static constexpr Phase kPhases[kCount] = {kBuildStart, kBuildFinish,
28-
kRasterStart, kRasterFinish};
25+
enum Phase {
26+
kVsyncStart,
27+
kBuildStart,
28+
kBuildFinish,
29+
kRasterStart,
30+
kRasterFinish,
31+
kCount
32+
};
33+
34+
static constexpr Phase kPhases[kCount] = {
35+
kVsyncStart, kBuildStart, kBuildFinish, kRasterStart, kRasterFinish};
2936

3037
fml::TimePoint Get(Phase phase) const { return data_[phase]; }
3138
fml::TimePoint Set(Phase phase, fml::TimePoint value) {

‎flow/layers/layer_tree.cc

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -21,8 +21,10 @@ LayerTree::LayerTree(const SkISize& frame_size,
2121
checkerboard_raster_cache_images_(false),
2222
checkerboard_offscreen_layers_(false) {}
2323

24-
void LayerTree::RecordBuildTime(fml::TimePoint build_start,
24+
void LayerTree::RecordBuildTime(fml::TimePoint vsync_start,
25+
fml::TimePoint build_start,
2526
fml::TimePoint target_time) {
27+
vsync_start_ = vsync_start;
2628
build_start_ = build_start;
2729
target_time_ = target_time;
2830
build_finish_ = fml::TimePoint::Now();

‎flow/layers/layer_tree.h

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -54,7 +54,11 @@ class LayerTree {
5454
float frame_physical_depth() const { return frame_physical_depth_; }
5555
float frame_device_pixel_ratio() const { return frame_device_pixel_ratio_; }
5656

57-
void RecordBuildTime(fml::TimePoint build_start, fml::TimePoint target_time);
57+
void RecordBuildTime(fml::TimePoint vsync_start,
58+
fml::TimePoint build_start,
59+
fml::TimePoint target_time);
60+
fml::TimePoint vsync_start() const { return vsync_start_; }
61+
fml::TimeDelta vsync_overhead() const { return build_start_ - vsync_start_; }
5862
fml::TimePoint build_start() const { return build_start_; }
5963
fml::TimePoint build_finish() const { return build_finish_; }
6064
fml::TimeDelta build_time() const { return build_finish_ - build_start_; }
@@ -83,6 +87,7 @@ class LayerTree {
8387

8488
private:
8589
std::shared_ptr<Layer> root_layer_;
90+
fml::TimePoint vsync_start_;
8691
fml::TimePoint build_start_;
8792
fml::TimePoint build_finish_;
8893
fml::TimePoint target_time_;

‎lib/ui/hooks.dart

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -200,7 +200,7 @@ void _reportTimings(List<int> timings) {
200200
assert(timings.length % FramePhase.values.length == 0);
201201
final List<FrameTiming> frameTimings = <FrameTiming>[];
202202
for (int i = 0; i < timings.length; i += FramePhase.values.length) {
203-
frameTimings.add(FrameTiming(timings.sublist(i, i + FramePhase.values.length)));
203+
frameTimings.add(FrameTiming._(timings.sublist(i, i + FramePhase.values.length)));
204204
}
205205
_invoke1(window.onReportTimings, window._onReportTimingsZone, frameTimings);
206206
}

‎lib/ui/window.dart

Lines changed: 37 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -47,6 +47,11 @@ typedef _SetNeedsReportTimingsFunc = void Function(bool value);
4747
///
4848
/// [FrameTiming] records a timestamp of each phase for performance analysis.
4949
enum FramePhase {
50+
/// The timestamp of the vsync signal given by the operating system.
51+
///
52+
/// See also [FrameTiming.vsyncOverhead].
53+
vsyncStart,
54+
5055
/// When the UI thread starts building a frame.
5156
///
5257
/// See also [FrameTiming.buildDuration].
@@ -82,14 +87,34 @@ enum FramePhase {
8287
/// Therefore it's recommended to only monitor and analyze performance metrics
8388
/// in profile and release modes.
8489
class FrameTiming {
90+
/// Construct [FrameTiming] with raw timestamps in microseconds.
91+
///
92+
/// This constructor is used for unit test only. Real [FrameTiming]s should
93+
/// be retrieved from [Window.onReportTimings].
94+
factory FrameTiming({
95+
required int vsyncStart,
96+
required int buildStart,
97+
required int buildFinish,
98+
required int rasterStart,
99+
required int rasterFinish,
100+
}) {
101+
return FrameTiming._(<int>[
102+
vsyncStart,
103+
buildStart,
104+
buildFinish,
105+
rasterStart,
106+
rasterFinish
107+
]);
108+
}
109+
85110
/// Construct [FrameTiming] with raw timestamps in microseconds.
86111
///
87112
/// List [timestamps] must have the same number of elements as
88113
/// [FramePhase.values].
89114
///
90115
/// This constructor is usually only called by the Flutter engine, or a test.
91116
/// To get the [FrameTiming] of your app, see [Window.onReportTimings].
92-
FrameTiming(List<int> timestamps)
117+
FrameTiming._(List<int> timestamps)
93118
: assert(timestamps.length == FramePhase.values.length), _timestamps = timestamps;
94119

95120
/// Construct [FrameTiming] with given timestamp in micrseconds.
@@ -106,7 +131,9 @@ class FrameTiming {
106131
required int rasterStart,
107132
required int rasterFinish
108133
}) {
109-
return FrameTiming(<int>[
134+
return FrameTiming._(<int>[
135+
// This is for temporarily backward compatiblilty.
136+
vsyncStart ?? buildStart,
110137
buildStart,
111138
buildFinish,
112139
rasterStart,
@@ -143,22 +170,26 @@ class FrameTiming {
143170
/// {@macro dart.ui.FrameTiming.fps_milliseconds}
144171
Duration get rasterDuration => _rawDuration(FramePhase.rasterFinish) - _rawDuration(FramePhase.rasterStart);
145172

146-
/// The timespan between build start and raster finish.
173+
/// The duration between receiving the vsync signal and starting building the
174+
/// frame.
175+
Duration get vsyncOverhead => _rawDuration(FramePhase.buildStart) - _rawDuration(FramePhase.vsyncStart);
176+
177+
/// The timespan between vsync start and raster finish.
147178
///
148179
/// To achieve the lowest latency on an X fps display, this should not exceed
149180
/// 1000/X milliseconds.
150181
/// {@macro dart.ui.FrameTiming.fps_milliseconds}
151182
///
152-
/// See also [buildDuration] and [rasterDuration].
153-
Duration get totalSpan => _rawDuration(FramePhase.rasterFinish) - _rawDuration(FramePhase.buildStart);
183+
/// See also [vsyncOverhead], [buildDuration] and [rasterDuration].
184+
Duration get totalSpan => _rawDuration(FramePhase.rasterFinish) - _rawDuration(FramePhase.vsyncStart);
154185

155186
final List<int> _timestamps; // in microseconds
156187

157188
String _formatMS(Duration duration) => '${duration.inMicroseconds * 0.001}ms';
158189

159190
@override
160191
String toString() {
161-
return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, totalSpan: ${_formatMS(totalSpan)})';
192+
return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, vsyncOverhead: ${_formatMS(vsyncOverhead)}, totalSpan: ${_formatMS(totalSpan)})';
162193
}
163194
}
164195

‎lib/web_ui/lib/src/ui/window.dart

Lines changed: 46 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1005,6 +1005,11 @@ class IsolateNameServer {
10051005
///
10061006
/// [FrameTiming] records a timestamp of each phase for performance analysis.
10071007
enum FramePhase {
1008+
/// The timestamp of the vsync signal given by the operating system.
1009+
///
1010+
/// See also [FrameTiming.vsyncOverhead].
1011+
vsyncStart,
1012+
10081013
/// When the UI thread starts building a frame.
10091014
///
10101015
/// See also [FrameTiming.buildDuration].
@@ -1035,16 +1040,35 @@ enum FramePhase {
10351040
/// Therefore it's recommended to only monitor and analyze performance metrics
10361041
/// in profile and release modes.
10371042
class FrameTiming {
1043+
/// Construct [FrameTiming] with raw timestamps in microseconds.
1044+
///
1045+
/// This constructor is used for unit test only. Real [FrameTiming]s should
1046+
/// be retrieved from [Window.onReportTimings].
1047+
factory FrameTiming({
1048+
required int vsyncStart,
1049+
required int buildStart,
1050+
required int buildFinish,
1051+
required int rasterStart,
1052+
required int rasterFinish,
1053+
}) {
1054+
return FrameTiming._(<int>[
1055+
vsyncStart,
1056+
buildStart,
1057+
buildFinish,
1058+
rasterStart,
1059+
rasterFinish
1060+
]);
1061+
}
1062+
10381063
/// Construct [FrameTiming] with raw timestamps in microseconds.
10391064
///
10401065
/// List [timestamps] must have the same number of elements as
10411066
/// [FramePhase.values].
10421067
///
10431068
/// This constructor is usually only called by the Flutter engine, or a test.
10441069
/// To get the [FrameTiming] of your app, see [Window.onReportTimings].
1045-
FrameTiming(List<int> timestamps)
1046-
: assert(timestamps.length == FramePhase.values.length),
1047-
_timestamps = timestamps;
1070+
FrameTiming._(List<int> timestamps)
1071+
: assert(timestamps.length == FramePhase.values.length), _timestamps = timestamps;
10481072

10491073
/// Construct [FrameTiming] with given timestamp in micrseconds.
10501074
///
@@ -1053,13 +1077,22 @@ class FrameTiming {
10531077
///
10541078
/// TODO(CareF): This is part of #20229. Remove back to default constructor
10551079
/// after #20229 lands and corresponding framwork PRs land.
1056-
FrameTiming.fromTimeStamps({
1080+
factory FrameTiming.fromTimeStamps({
10571081
int? vsyncStart,
10581082
required int buildStart,
10591083
required int buildFinish,
10601084
required int rasterStart,
10611085
required int rasterFinish
1062-
}) : _timestamps = <int>[buildStart, buildFinish, rasterStart, rasterFinish];
1086+
}) {
1087+
return FrameTiming._(<int>[
1088+
// This is for temporarily backward compatiblilty.
1089+
vsyncStart ?? buildStart,
1090+
buildStart,
1091+
buildFinish,
1092+
rasterStart,
1093+
rasterFinish
1094+
]);
1095+
}
10631096

10641097
/// This is a raw timestamp in microseconds from some epoch. The epoch in all
10651098
/// [FrameTiming] is the same, but it may not match [DateTime]'s epoch.
@@ -1095,24 +1128,28 @@ class FrameTiming {
10951128
_rawDuration(FramePhase.rasterFinish) -
10961129
_rawDuration(FramePhase.rasterStart);
10971130

1098-
/// The timespan between build start and raster finish.
1131+
/// The duration between receiving the vsync signal and starting building the
1132+
/// frame.
1133+
Duration get vsyncOverhead => _rawDuration(FramePhase.buildStart) - _rawDuration(FramePhase.vsyncStart);
1134+
1135+
/// The timespan between vsync start and raster finish.
10991136
///
11001137
/// To achieve the lowest latency on an X fps display, this should not exceed
11011138
/// 1000/X milliseconds.
11021139
/// {@macro dart.ui.FrameTiming.fps_milliseconds}
11031140
///
1104-
/// See also [buildDuration] and [rasterDuration].
1141+
/// See also [vsyncOverhead], [buildDuration] and [rasterDuration].
11051142
Duration get totalSpan =>
11061143
_rawDuration(FramePhase.rasterFinish) -
1107-
_rawDuration(FramePhase.buildStart);
1144+
_rawDuration(FramePhase.vsyncStart);
11081145

11091146
final List<int> _timestamps; // in microseconds
11101147

11111148
String _formatMS(Duration duration) => '${duration.inMicroseconds * 0.001}ms';
11121149

11131150
@override
11141151
String toString() {
1115-
return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, totalSpan: ${_formatMS(totalSpan)})';
1152+
return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, vsyncOverhead: ${_formatMS(vsyncOverhead)}, totalSpan: ${_formatMS(totalSpan)})';
11161153
}
11171154
}
11181155

‎shell/common/animator.cc

Lines changed: 11 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ Animator::Animator(Delegate& delegate,
2626
task_runners_(std::move(task_runners)),
2727
waiter_(std::move(waiter)),
2828
last_frame_begin_time_(),
29+
last_vsync_start_time_(),
2930
last_frame_target_time_(),
3031
dart_frame_deadline_(0),
3132
#if FLUTTER_SHELL_ENABLE_METAL
@@ -98,7 +99,7 @@ static int64_t FxlToDartOrEarlier(fml::TimePoint time) {
9899
return (time - fxl_now).ToMicroseconds() + dart_now;
99100
}
100101

101-
void Animator::BeginFrame(fml::TimePoint frame_start_time,
102+
void Animator::BeginFrame(fml::TimePoint vsync_start_time,
102103
fml::TimePoint frame_target_time) {
103104
TRACE_EVENT_ASYNC_END0("flutter", "Frame Request Pending", frame_number_++);
104105

@@ -133,7 +134,11 @@ void Animator::BeginFrame(fml::TimePoint frame_start_time,
133134
// to service potential frame.
134135
FML_DCHECK(producer_continuation_);
135136

136-
last_frame_begin_time_ = frame_start_time;
137+
last_frame_begin_time_ = fml::TimePoint::Now();
138+
last_vsync_start_time_ = vsync_start_time;
139+
fml::tracing::TraceEventAsyncComplete("flutter", "VsyncSchedulingOverhead",
140+
last_vsync_start_time_,
141+
last_frame_begin_time_);
137142
last_frame_target_time_ = frame_target_time;
138143
dart_frame_deadline_ = FxlToDartOrEarlier(frame_target_time);
139144
{
@@ -179,7 +184,8 @@ void Animator::Render(std::unique_ptr<flutter::LayerTree> layer_tree) {
179184
last_layer_tree_size_ = layer_tree->frame_size();
180185

181186
// Note the frame time for instrumentation.
182-
layer_tree->RecordBuildTime(last_frame_begin_time_, last_frame_target_time_);
187+
layer_tree->RecordBuildTime(last_vsync_start_time_, last_frame_begin_time_,
188+
last_frame_target_time_);
183189

184190
// Commit the pending continuation.
185191
bool result = producer_continuation_.Complete(std::move(layer_tree));
@@ -233,13 +239,13 @@ void Animator::RequestFrame(bool regenerate_layer_tree) {
233239

234240
void Animator::AwaitVSync() {
235241
waiter_->AsyncWaitForVsync(
236-
[self = weak_factory_.GetWeakPtr()](fml::TimePoint frame_start_time,
242+
[self = weak_factory_.GetWeakPtr()](fml::TimePoint vsync_start_time,
237243
fml::TimePoint frame_target_time) {
238244
if (self) {
239245
if (self->CanReuseLastLayerTree()) {
240246
self->DrawLastLayerTree();
241247
} else {
242-
self->BeginFrame(frame_start_time, frame_target_time);
248+
self->BeginFrame(vsync_start_time, frame_target_time);
243249
}
244250
}
245251
});

‎shell/common/animator.h

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -98,6 +98,7 @@ class Animator final {
9898
std::shared_ptr<VsyncWaiter> waiter_;
9999

100100
fml::TimePoint last_frame_begin_time_;
101+
fml::TimePoint last_vsync_start_time_;
101102
fml::TimePoint last_frame_target_time_;
102103
int64_t dart_frame_deadline_;
103104
fml::RefPtr<LayerTreePipeline> layer_tree_pipeline_;

‎shell/common/rasterizer.cc

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -290,6 +290,7 @@ RasterStatus Rasterizer::DoDraw(
290290
#if !defined(OS_FUCHSIA)
291291
const fml::TimePoint frame_target_time = layer_tree->target_time();
292292
#endif
293+
timing.Set(FrameTiming::kVsyncStart, layer_tree->vsync_start());
293294
timing.Set(FrameTiming::kBuildStart, layer_tree->build_start());
294295
timing.Set(FrameTiming::kBuildFinish, layer_tree->build_finish());
295296
timing.Set(FrameTiming::kRasterStart, fml::TimePoint::Now());

‎shell/common/vsync_waiter.cc

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -122,9 +122,6 @@ void VsyncWaiter::FireCallback(fml::TimePoint frame_start_time,
122122
[callback, flow_identifier, frame_start_time, frame_target_time]() {
123123
FML_TRACE_EVENT("flutter", kVsyncTraceName, "StartTime",
124124
frame_start_time, "TargetTime", frame_target_time);
125-
fml::tracing::TraceEventAsyncComplete(
126-
"flutter", "VsyncSchedulingOverhead", fml::TimePoint::Now(),
127-
frame_start_time);
128125
callback(frame_start_time, frame_target_time);
129126
TRACE_FLOW_END("flutter", kVsyncFlowName, flow_identifier);
130127
},

‎testing/dart/window_test.dart

Lines changed: 8 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -22,8 +22,14 @@ void main() {
2222
});
2323

2424
test('FrameTiming.toString has the correct format', () {
25-
final FrameTiming timing = FrameTiming(<int>[1000, 8000, 9000, 19500]);
26-
expect(timing.toString(), 'FrameTiming(buildDuration: 7.0ms, rasterDuration: 10.5ms, totalSpan: 18.5ms)');
25+
final FrameTiming timing = FrameTiming(
26+
vsyncStart: 500,
27+
buildStart: 1000,
28+
buildFinish: 8000,
29+
rasterStart: 9000,
30+
rasterFinish: 19500
31+
);
32+
expect(timing.toString(), 'FrameTiming(buildDuration: 7.0ms, rasterDuration: 10.5ms, vsyncOverhead: 0.5ms, totalSpan: 19.0ms)');
2733
});
2834

2935
test('computePlatformResolvedLocale basic', () {

0 commit comments

Comments
 (0)