diff --git a/common/settings.h b/common/settings.h index 15166b8d38213..1f3bb0ed750df 100644 --- a/common/settings.h +++ b/common/settings.h @@ -22,10 +22,17 @@ namespace flutter { class FrameTiming { public: - enum Phase { kBuildStart, kBuildFinish, kRasterStart, kRasterFinish, kCount }; - - static constexpr Phase kPhases[kCount] = {kBuildStart, kBuildFinish, - kRasterStart, kRasterFinish}; + enum Phase { + kVsyncStart, + kBuildStart, + kBuildFinish, + kRasterStart, + kRasterFinish, + kCount + }; + + static constexpr Phase kPhases[kCount] = { + kVsyncStart, kBuildStart, kBuildFinish, kRasterStart, kRasterFinish}; fml::TimePoint Get(Phase phase) const { return data_[phase]; } fml::TimePoint Set(Phase phase, fml::TimePoint value) { diff --git a/flow/layers/layer_tree.cc b/flow/layers/layer_tree.cc index 0f598ae6f153f..121391d69a3ba 100644 --- a/flow/layers/layer_tree.cc +++ b/flow/layers/layer_tree.cc @@ -21,8 +21,10 @@ LayerTree::LayerTree(const SkISize& frame_size, checkerboard_raster_cache_images_(false), checkerboard_offscreen_layers_(false) {} -void LayerTree::RecordBuildTime(fml::TimePoint build_start, +void LayerTree::RecordBuildTime(fml::TimePoint vsync_start, + fml::TimePoint build_start, fml::TimePoint target_time) { + vsync_start_ = vsync_start; build_start_ = build_start; target_time_ = target_time; build_finish_ = fml::TimePoint::Now(); diff --git a/flow/layers/layer_tree.h b/flow/layers/layer_tree.h index 733284afe65db..0ecd610c9737d 100644 --- a/flow/layers/layer_tree.h +++ b/flow/layers/layer_tree.h @@ -54,7 +54,11 @@ class LayerTree { float frame_physical_depth() const { return frame_physical_depth_; } float frame_device_pixel_ratio() const { return frame_device_pixel_ratio_; } - void RecordBuildTime(fml::TimePoint build_start, fml::TimePoint target_time); + void RecordBuildTime(fml::TimePoint vsync_start, + fml::TimePoint build_start, + fml::TimePoint target_time); + fml::TimePoint vsync_start() const { return vsync_start_; } + fml::TimeDelta vsync_overhead() const { return build_start_ - vsync_start_; } fml::TimePoint build_start() const { return build_start_; } fml::TimePoint build_finish() const { return build_finish_; } fml::TimeDelta build_time() const { return build_finish_ - build_start_; } @@ -83,6 +87,7 @@ class LayerTree { private: std::shared_ptr root_layer_; + fml::TimePoint vsync_start_; fml::TimePoint build_start_; fml::TimePoint build_finish_; fml::TimePoint target_time_; diff --git a/lib/ui/hooks.dart b/lib/ui/hooks.dart index c01095412a606..c2a74aa10c3ec 100644 --- a/lib/ui/hooks.dart +++ b/lib/ui/hooks.dart @@ -200,7 +200,7 @@ void _reportTimings(List timings) { assert(timings.length % FramePhase.values.length == 0); final List frameTimings = []; for (int i = 0; i < timings.length; i += FramePhase.values.length) { - frameTimings.add(FrameTiming(timings.sublist(i, i + FramePhase.values.length))); + frameTimings.add(FrameTiming._(timings.sublist(i, i + FramePhase.values.length))); } _invoke1(window.onReportTimings, window._onReportTimingsZone, frameTimings); } diff --git a/lib/ui/window.dart b/lib/ui/window.dart index 90c5603c1552f..4bc5e2ec5fe3f 100644 --- a/lib/ui/window.dart +++ b/lib/ui/window.dart @@ -47,6 +47,11 @@ typedef _SetNeedsReportTimingsFunc = void Function(bool value); /// /// [FrameTiming] records a timestamp of each phase for performance analysis. enum FramePhase { + /// The timestamp of the vsync signal given by the operating system. + /// + /// See also [FrameTiming.vsyncOverhead]. + vsyncStart, + /// When the UI thread starts building a frame. /// /// See also [FrameTiming.buildDuration]. @@ -82,6 +87,26 @@ enum FramePhase { /// Therefore it's recommended to only monitor and analyze performance metrics /// in profile and release modes. class FrameTiming { + /// Construct [FrameTiming] with raw timestamps in microseconds. + /// + /// This constructor is used for unit test only. Real [FrameTiming]s should + /// be retrieved from [Window.onReportTimings]. + factory FrameTiming({ + required int vsyncStart, + required int buildStart, + required int buildFinish, + required int rasterStart, + required int rasterFinish, + }) { + return FrameTiming._([ + vsyncStart, + buildStart, + buildFinish, + rasterStart, + rasterFinish + ]); + } + /// Construct [FrameTiming] with raw timestamps in microseconds. /// /// List [timestamps] must have the same number of elements as @@ -89,7 +114,7 @@ class FrameTiming { /// /// This constructor is usually only called by the Flutter engine, or a test. /// To get the [FrameTiming] of your app, see [Window.onReportTimings]. - FrameTiming(List timestamps) + FrameTiming._(List timestamps) : assert(timestamps.length == FramePhase.values.length), _timestamps = timestamps; /// Construct [FrameTiming] with given timestamp in micrseconds. @@ -106,7 +131,9 @@ class FrameTiming { required int rasterStart, required int rasterFinish }) { - return FrameTiming([ + return FrameTiming._([ + // This is for temporarily backward compatiblilty. + vsyncStart ?? buildStart, buildStart, buildFinish, rasterStart, @@ -143,14 +170,18 @@ class FrameTiming { /// {@macro dart.ui.FrameTiming.fps_milliseconds} Duration get rasterDuration => _rawDuration(FramePhase.rasterFinish) - _rawDuration(FramePhase.rasterStart); - /// The timespan between build start and raster finish. + /// The duration between receiving the vsync signal and starting building the + /// frame. + Duration get vsyncOverhead => _rawDuration(FramePhase.buildStart) - _rawDuration(FramePhase.vsyncStart); + + /// The timespan between vsync start and raster finish. /// /// To achieve the lowest latency on an X fps display, this should not exceed /// 1000/X milliseconds. /// {@macro dart.ui.FrameTiming.fps_milliseconds} /// - /// See also [buildDuration] and [rasterDuration]. - Duration get totalSpan => _rawDuration(FramePhase.rasterFinish) - _rawDuration(FramePhase.buildStart); + /// See also [vsyncOverhead], [buildDuration] and [rasterDuration]. + Duration get totalSpan => _rawDuration(FramePhase.rasterFinish) - _rawDuration(FramePhase.vsyncStart); final List _timestamps; // in microseconds @@ -158,7 +189,7 @@ class FrameTiming { @override String toString() { - return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, totalSpan: ${_formatMS(totalSpan)})'; + return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, vsyncOverhead: ${_formatMS(vsyncOverhead)}, totalSpan: ${_formatMS(totalSpan)})'; } } diff --git a/lib/web_ui/lib/src/ui/window.dart b/lib/web_ui/lib/src/ui/window.dart index cbe7465a69fc0..b90051e637c77 100644 --- a/lib/web_ui/lib/src/ui/window.dart +++ b/lib/web_ui/lib/src/ui/window.dart @@ -1005,6 +1005,11 @@ class IsolateNameServer { /// /// [FrameTiming] records a timestamp of each phase for performance analysis. enum FramePhase { + /// The timestamp of the vsync signal given by the operating system. + /// + /// See also [FrameTiming.vsyncOverhead]. + vsyncStart, + /// When the UI thread starts building a frame. /// /// See also [FrameTiming.buildDuration]. @@ -1035,6 +1040,26 @@ enum FramePhase { /// Therefore it's recommended to only monitor and analyze performance metrics /// in profile and release modes. class FrameTiming { + /// Construct [FrameTiming] with raw timestamps in microseconds. + /// + /// This constructor is used for unit test only. Real [FrameTiming]s should + /// be retrieved from [Window.onReportTimings]. + factory FrameTiming({ + required int vsyncStart, + required int buildStart, + required int buildFinish, + required int rasterStart, + required int rasterFinish, + }) { + return FrameTiming._([ + vsyncStart, + buildStart, + buildFinish, + rasterStart, + rasterFinish + ]); + } + /// Construct [FrameTiming] with raw timestamps in microseconds. /// /// List [timestamps] must have the same number of elements as @@ -1042,9 +1067,8 @@ class FrameTiming { /// /// This constructor is usually only called by the Flutter engine, or a test. /// To get the [FrameTiming] of your app, see [Window.onReportTimings]. - FrameTiming(List timestamps) - : assert(timestamps.length == FramePhase.values.length), - _timestamps = timestamps; + FrameTiming._(List timestamps) + : assert(timestamps.length == FramePhase.values.length), _timestamps = timestamps; /// Construct [FrameTiming] with given timestamp in micrseconds. /// @@ -1053,13 +1077,22 @@ class FrameTiming { /// /// TODO(CareF): This is part of #20229. Remove back to default constructor /// after #20229 lands and corresponding framwork PRs land. - FrameTiming.fromTimeStamps({ + factory FrameTiming.fromTimeStamps({ int? vsyncStart, required int buildStart, required int buildFinish, required int rasterStart, required int rasterFinish - }) : _timestamps = [buildStart, buildFinish, rasterStart, rasterFinish]; + }) { + return FrameTiming._([ + // This is for temporarily backward compatiblilty. + vsyncStart ?? buildStart, + buildStart, + buildFinish, + rasterStart, + rasterFinish + ]); + } /// This is a raw timestamp in microseconds from some epoch. The epoch in all /// [FrameTiming] is the same, but it may not match [DateTime]'s epoch. @@ -1095,16 +1128,20 @@ class FrameTiming { _rawDuration(FramePhase.rasterFinish) - _rawDuration(FramePhase.rasterStart); - /// The timespan between build start and raster finish. + /// The duration between receiving the vsync signal and starting building the + /// frame. + Duration get vsyncOverhead => _rawDuration(FramePhase.buildStart) - _rawDuration(FramePhase.vsyncStart); + + /// The timespan between vsync start and raster finish. /// /// To achieve the lowest latency on an X fps display, this should not exceed /// 1000/X milliseconds. /// {@macro dart.ui.FrameTiming.fps_milliseconds} /// - /// See also [buildDuration] and [rasterDuration]. + /// See also [vsyncOverhead], [buildDuration] and [rasterDuration]. Duration get totalSpan => _rawDuration(FramePhase.rasterFinish) - - _rawDuration(FramePhase.buildStart); + _rawDuration(FramePhase.vsyncStart); final List _timestamps; // in microseconds @@ -1112,7 +1149,7 @@ class FrameTiming { @override String toString() { - return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, totalSpan: ${_formatMS(totalSpan)})'; + return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, vsyncOverhead: ${_formatMS(vsyncOverhead)}, totalSpan: ${_formatMS(totalSpan)})'; } } diff --git a/shell/common/animator.cc b/shell/common/animator.cc index 2237d1ffed3d4..3ca1a83788773 100644 --- a/shell/common/animator.cc +++ b/shell/common/animator.cc @@ -26,6 +26,7 @@ Animator::Animator(Delegate& delegate, task_runners_(std::move(task_runners)), waiter_(std::move(waiter)), last_frame_begin_time_(), + last_vsync_start_time_(), last_frame_target_time_(), dart_frame_deadline_(0), #if FLUTTER_SHELL_ENABLE_METAL @@ -98,7 +99,7 @@ static int64_t FxlToDartOrEarlier(fml::TimePoint time) { return (time - fxl_now).ToMicroseconds() + dart_now; } -void Animator::BeginFrame(fml::TimePoint frame_start_time, +void Animator::BeginFrame(fml::TimePoint vsync_start_time, fml::TimePoint frame_target_time) { TRACE_EVENT_ASYNC_END0("flutter", "Frame Request Pending", frame_number_++); @@ -133,7 +134,11 @@ void Animator::BeginFrame(fml::TimePoint frame_start_time, // to service potential frame. FML_DCHECK(producer_continuation_); - last_frame_begin_time_ = frame_start_time; + last_frame_begin_time_ = fml::TimePoint::Now(); + last_vsync_start_time_ = vsync_start_time; + fml::tracing::TraceEventAsyncComplete("flutter", "VsyncSchedulingOverhead", + last_vsync_start_time_, + last_frame_begin_time_); last_frame_target_time_ = frame_target_time; dart_frame_deadline_ = FxlToDartOrEarlier(frame_target_time); { @@ -179,7 +184,8 @@ void Animator::Render(std::unique_ptr layer_tree) { last_layer_tree_size_ = layer_tree->frame_size(); // Note the frame time for instrumentation. - layer_tree->RecordBuildTime(last_frame_begin_time_, last_frame_target_time_); + layer_tree->RecordBuildTime(last_vsync_start_time_, last_frame_begin_time_, + last_frame_target_time_); // Commit the pending continuation. bool result = producer_continuation_.Complete(std::move(layer_tree)); @@ -233,13 +239,13 @@ void Animator::RequestFrame(bool regenerate_layer_tree) { void Animator::AwaitVSync() { waiter_->AsyncWaitForVsync( - [self = weak_factory_.GetWeakPtr()](fml::TimePoint frame_start_time, + [self = weak_factory_.GetWeakPtr()](fml::TimePoint vsync_start_time, fml::TimePoint frame_target_time) { if (self) { if (self->CanReuseLastLayerTree()) { self->DrawLastLayerTree(); } else { - self->BeginFrame(frame_start_time, frame_target_time); + self->BeginFrame(vsync_start_time, frame_target_time); } } }); diff --git a/shell/common/animator.h b/shell/common/animator.h index 0bab57730015a..a6508fe24fa1a 100644 --- a/shell/common/animator.h +++ b/shell/common/animator.h @@ -98,6 +98,7 @@ class Animator final { std::shared_ptr waiter_; fml::TimePoint last_frame_begin_time_; + fml::TimePoint last_vsync_start_time_; fml::TimePoint last_frame_target_time_; int64_t dart_frame_deadline_; fml::RefPtr layer_tree_pipeline_; diff --git a/shell/common/rasterizer.cc b/shell/common/rasterizer.cc index d43867876fd87..c9514c2ac056d 100644 --- a/shell/common/rasterizer.cc +++ b/shell/common/rasterizer.cc @@ -290,6 +290,7 @@ RasterStatus Rasterizer::DoDraw( #if !defined(OS_FUCHSIA) const fml::TimePoint frame_target_time = layer_tree->target_time(); #endif + timing.Set(FrameTiming::kVsyncStart, layer_tree->vsync_start()); timing.Set(FrameTiming::kBuildStart, layer_tree->build_start()); timing.Set(FrameTiming::kBuildFinish, layer_tree->build_finish()); timing.Set(FrameTiming::kRasterStart, fml::TimePoint::Now()); diff --git a/shell/common/vsync_waiter.cc b/shell/common/vsync_waiter.cc index ae86fc547ea3b..7947d42cf6125 100644 --- a/shell/common/vsync_waiter.cc +++ b/shell/common/vsync_waiter.cc @@ -122,9 +122,6 @@ void VsyncWaiter::FireCallback(fml::TimePoint frame_start_time, [callback, flow_identifier, frame_start_time, frame_target_time]() { FML_TRACE_EVENT("flutter", kVsyncTraceName, "StartTime", frame_start_time, "TargetTime", frame_target_time); - fml::tracing::TraceEventAsyncComplete( - "flutter", "VsyncSchedulingOverhead", fml::TimePoint::Now(), - frame_start_time); callback(frame_start_time, frame_target_time); TRACE_FLOW_END("flutter", kVsyncFlowName, flow_identifier); }, diff --git a/testing/dart/window_test.dart b/testing/dart/window_test.dart index a434482024d69..79767f881e7bc 100644 --- a/testing/dart/window_test.dart +++ b/testing/dart/window_test.dart @@ -22,8 +22,14 @@ void main() { }); test('FrameTiming.toString has the correct format', () { - final FrameTiming timing = FrameTiming([1000, 8000, 9000, 19500]); - expect(timing.toString(), 'FrameTiming(buildDuration: 7.0ms, rasterDuration: 10.5ms, totalSpan: 18.5ms)'); + final FrameTiming timing = FrameTiming( + vsyncStart: 500, + buildStart: 1000, + buildFinish: 8000, + rasterStart: 9000, + rasterFinish: 19500 + ); + expect(timing.toString(), 'FrameTiming(buildDuration: 7.0ms, rasterDuration: 10.5ms, vsyncOverhead: 0.5ms, totalSpan: 19.0ms)'); }); test('computePlatformResolvedLocale basic', () {