diff --git a/common/settings.cc b/common/settings.cc index 7dae838f4ac7f..7a552f3d8e7a3 100644 --- a/common/settings.cc +++ b/common/settings.cc @@ -8,6 +8,8 @@ namespace flutter { +constexpr FrameTiming::Phase FrameTiming::kPhases[FrameTiming::kCount]; + Settings::Settings() = default; Settings::Settings(const Settings& other) = default; @@ -51,6 +53,8 @@ std::string Settings::ToString() const { stream << "icu_data_path: " << icu_data_path << std::endl; stream << "assets_dir: " << assets_dir << std::endl; stream << "assets_path: " << assets_path << std::endl; + stream << "frame_rasterized_callback set: " << !!frame_rasterized_callback + << std::endl; return stream.str(); } diff --git a/common/settings.h b/common/settings.h index 58f940535291e..7a820ce3d21e9 100644 --- a/common/settings.h +++ b/common/settings.h @@ -14,10 +14,27 @@ #include "flutter/fml/closure.h" #include "flutter/fml/mapping.h" +#include "flutter/fml/time/time_point.h" #include "flutter/fml/unique_fd.h" namespace flutter { +class FrameTiming { + public: + enum Phase { kBuildStart, kBuildFinish, kRasterStart, kRasterFinish, kCount }; + + static constexpr Phase kPhases[kCount] = {kBuildStart, kBuildFinish, + kRasterStart, kRasterFinish}; + + fml::TimePoint Get(Phase phase) const { return data_[phase]; } + fml::TimePoint Set(Phase phase, fml::TimePoint value) { + return data_[phase] = value; + } + + private: + fml::TimePoint data_[kCount]; +}; + using TaskObserverAdd = std::function; using TaskObserverRemove = std::function; @@ -32,6 +49,8 @@ using MappingCallback = std::function(void)>; using MappingsCallback = std::function>(void)>; +using FrameRasterizedCallback = std::function; + struct Settings { Settings(); @@ -149,6 +168,10 @@ struct Settings { fml::UniqueFD::traits_type::InvalidValue(); std::string assets_path; + // Callback to handle the timings of a rasterized frame. This is called as + // soon as a frame is rasterized. + FrameRasterizedCallback frame_rasterized_callback; + std::string ToString() const; }; diff --git a/flow/layers/layer_tree.cc b/flow/layers/layer_tree.cc index 70c21604dedb3..5de5f9a48fba9 100644 --- a/flow/layers/layer_tree.cc +++ b/flow/layers/layer_tree.cc @@ -19,6 +19,11 @@ LayerTree::LayerTree() LayerTree::~LayerTree() = default; +void LayerTree::RecordBuildTime(fml::TimePoint start) { + build_start_ = start; + build_finish_ = fml::TimePoint::Now(); +} + void LayerTree::Preroll(CompositorContext::ScopedFrame& frame, bool ignore_raster_cache) { TRACE_EVENT0("flutter", "LayerTree::Preroll"); diff --git a/flow/layers/layer_tree.h b/flow/layers/layer_tree.h index 641948bcf77ff..920fd166db93b 100644 --- a/flow/layers/layer_tree.h +++ b/flow/layers/layer_tree.h @@ -47,11 +47,10 @@ class LayerTree { void set_frame_size(const SkISize& frame_size) { frame_size_ = frame_size; } - void set_construction_time(const fml::TimeDelta& delta) { - construction_time_ = delta; - } - - const fml::TimeDelta& construction_time() const { return construction_time_; } + void RecordBuildTime(fml::TimePoint begin_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_; } // The number of frame intervals missed after which the compositor must // trace the rasterized picture to a trace file. Specify 0 to disable all @@ -75,7 +74,8 @@ class LayerTree { private: SkISize frame_size_; // Physical pixels. std::shared_ptr root_layer_; - fml::TimeDelta construction_time_; + fml::TimePoint build_start_; + fml::TimePoint build_finish_; uint32_t rasterizer_tracing_threshold_; bool checkerboard_raster_cache_images_; bool checkerboard_offscreen_layers_; diff --git a/lib/stub_ui/lib/src/ui/window.dart b/lib/stub_ui/lib/src/ui/window.dart index 7bcfdb83dc98e..420e0a36cf3e5 100644 --- a/lib/stub_ui/lib/src/ui/window.dart +++ b/lib/stub_ui/lib/src/ui/window.dart @@ -32,6 +32,98 @@ typedef PlatformMessageResponseCallback = void Function(ByteData data); typedef PlatformMessageCallback = void Function( String name, ByteData data, PlatformMessageResponseCallback callback); +/// Various important time points in the lifetime of a frame. +/// +/// [FrameTiming] records a timestamp of each phase for performance analysis. +enum FramePhase { + /// When the UI thread starts building a frame. + /// + /// See also [FrameTiming.buildDuration]. + buildStart, + + /// When the UI thread finishes building a frame. + /// + /// See also [FrameTiming.buildDuration]. + buildFinish, + + /// When the GPU thread starts rasterizing a frame. + /// + /// See also [FrameTiming.rasterDuration]. + rasterStart, + + /// When the GPU thread finishes rasterizing a frame. + /// + /// See also [FrameTiming.rasterDuration]. + rasterFinish, +} + +/// Time-related performance metrics of a frame. +/// +/// See [Window.onReportTimings] for how to get this. +/// +/// The metrics in debug mode (`flutter run` without any flags) may be very +/// different from those in profile and release modes due to the debug overhead. +/// 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. + /// + /// List [timestamps] must have the same number of elements as + /// [FramePhase.values]. + /// + /// 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; + + /// 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. + int timestampInMicroseconds(FramePhase phase) => _timestamps[phase.index]; + + Duration _rawDuration(FramePhase phase) => Duration(microseconds: _timestamps[phase.index]); + + /// The duration to build the frame on the UI thread. + /// + /// The build starts approximately when [Window.onBeginFrame] is called. The + /// [Duration] in the [Window.onBeginFrame] callback is exactly the + /// `Duration(microseconds: timestampInMicroseconds(FramePhase.buildStart))`. + /// + /// The build finishes when [Window.render] is called. + /// + /// {@template dart.ui.FrameTiming.fps_smoothness_milliseconds} + /// To ensure smooth animations of X fps, this should not exceed 1000/X + /// milliseconds. + /// {@endtemplate} + /// {@template dart.ui.FrameTiming.fps_milliseconds} + /// That's about 16ms for 60fps, and 8ms for 120fps. + /// {@endtemplate} + Duration get buildDuration => _rawDuration(FramePhase.buildFinish) - _rawDuration(FramePhase.buildStart); + + /// The duration to rasterize the frame on the GPU thread. + /// + /// {@macro dart.ui.FrameTiming.fps_smoothness_milliseconds} + /// {@macro dart.ui.FrameTiming.fps_milliseconds} + Duration get rasterDuration => _rawDuration(FramePhase.rasterFinish) - _rawDuration(FramePhase.rasterStart); + + /// The timespan between build 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); + + final List _timestamps; // in microseconds + + String _formatMS(Duration duration) => '${duration.inMicroseconds * 0.001}ms'; + + @override + String toString() { + return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, totalSpan: ${_formatMS(totalSpan)})'; + } +} + /// States that an application can be in. /// /// The values below describe notifications from the operating system. @@ -771,6 +863,30 @@ abstract class Window { _onDrawFrame = callback; } + /// A callback that is invoked to report the [FrameTiming] of recently + /// rasterized frames. + /// + /// This can be used to see if the application has missed frames (through + /// [FrameTiming.buildDuration] and [FrameTiming.rasterDuration]), or high + /// latencies (through [FrameTiming.totalSpan]). + /// + /// Unlike [Timeline], the timing information here is available in the release + /// mode (additional to the profile and the debug mode). Hence this can be + /// used to monitor the application's performance in the wild. + /// + /// The callback may not be immediately triggered after each frame. Instead, + /// it tries to batch frames together and send all their timings at once to + /// decrease the overhead (as this is available in the release mode). The + /// timing of any frame will be sent within about 1 second even if there are + /// no later frames to batch. + TimingsCallback get onReportTimings => _onReportTimings; + TimingsCallback _onReportTimings; + Zone _onReportTimingsZone; + set onReportTimings(TimingsCallback callback) { + _onReportTimings = callback; + _onReportTimingsZone = Zone.current; + } + /// A callback that is invoked when pointer data is available. /// /// The framework invokes this callback in the same zone in which the diff --git a/lib/ui/hooks.dart b/lib/ui/hooks.dart index 36b5a078140b3..9378857e9628a 100644 --- a/lib/ui/hooks.dart +++ b/lib/ui/hooks.dart @@ -177,6 +177,17 @@ void _beginFrame(int microseconds) { _invoke1(window.onBeginFrame, window._onBeginFrameZone, Duration(microseconds: microseconds)); } +@pragma('vm:entry-point') +// ignore: unused_element +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))); + } + _invoke1(window.onReportTimings, window._onReportTimingsZone, frameTimings); +} + @pragma('vm:entry-point') // ignore: unused_element void _drawFrame() { diff --git a/lib/ui/window.dart b/lib/ui/window.dart index 2ae620be6895f..447100769b476 100644 --- a/lib/ui/window.dart +++ b/lib/ui/window.dart @@ -10,6 +10,18 @@ typedef VoidCallback = void Function(); /// Signature for [Window.onBeginFrame]. typedef FrameCallback = void Function(Duration duration); +/// Signature for [Window.onReportTimings]. +/// +/// {@template dart.ui.TimingsCallback.list} +/// The callback takes a list of [FrameTiming] because it may not be immediately +/// triggered after each frame. Instead, Flutter tries to batch frames together +/// and send all their timings at once to decrease the overhead (as this is +/// available in the release mode). The list is sorted in ascending order of +/// time (earliest frame first). The timing of any frame will be sent within +/// about 1 second even if there are no later frames to batch. +/// {@endtemplate} +typedef TimingsCallback = void Function(List timings); + /// Signature for [Window.onPointerDataPacket]. typedef PointerDataPacketCallback = void Function(PointerDataPacket packet); @@ -25,6 +37,98 @@ typedef PlatformMessageResponseCallback = void Function(ByteData data); /// Signature for [Window.onPlatformMessage]. typedef PlatformMessageCallback = void Function(String name, ByteData data, PlatformMessageResponseCallback callback); +/// Various important time points in the lifetime of a frame. +/// +/// [FrameTiming] records a timestamp of each phase for performance analysis. +enum FramePhase { + /// When the UI thread starts building a frame. + /// + /// See also [FrameTiming.buildDuration]. + buildStart, + + /// When the UI thread finishes building a frame. + /// + /// See also [FrameTiming.buildDuration]. + buildFinish, + + /// When the GPU thread starts rasterizing a frame. + /// + /// See also [FrameTiming.rasterDuration]. + rasterStart, + + /// When the GPU thread finishes rasterizing a frame. + /// + /// See also [FrameTiming.rasterDuration]. + rasterFinish, +} + +/// Time-related performance metrics of a frame. +/// +/// See [Window.onReportTimings] for how to get this. +/// +/// The metrics in debug mode (`flutter run` without any flags) may be very +/// different from those in profile and release modes due to the debug overhead. +/// 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. + /// + /// List [timestamps] must have the same number of elements as + /// [FramePhase.values]. + /// + /// 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; + + /// 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. + int timestampInMicroseconds(FramePhase phase) => _timestamps[phase.index]; + + Duration _rawDuration(FramePhase phase) => Duration(microseconds: _timestamps[phase.index]); + + /// The duration to build the frame on the UI thread. + /// + /// The build starts approximately when [Window.onBeginFrame] is called. The + /// [Duration] in the [Window.onBeginFrame] callback is exactly the + /// `Duration(microseconds: timestampInMicroseconds(FramePhase.buildStart))`. + /// + /// The build finishes when [Window.render] is called. + /// + /// {@template dart.ui.FrameTiming.fps_smoothness_milliseconds} + /// To ensure smooth animations of X fps, this should not exceed 1000/X + /// milliseconds. + /// {@endtemplate} + /// {@template dart.ui.FrameTiming.fps_milliseconds} + /// That's about 16ms for 60fps, and 8ms for 120fps. + /// {@endtemplate} + Duration get buildDuration => _rawDuration(FramePhase.buildFinish) - _rawDuration(FramePhase.buildStart); + + /// The duration to rasterize the frame on the GPU thread. + /// + /// {@macro dart.ui.FrameTiming.fps_smoothness_milliseconds} + /// {@macro dart.ui.FrameTiming.fps_milliseconds} + Duration get rasterDuration => _rawDuration(FramePhase.rasterFinish) - _rawDuration(FramePhase.rasterStart); + + /// The timespan between build 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); + + final List _timestamps; // in microseconds + + String _formatMS(Duration duration) => '${duration.inMicroseconds * 0.001}ms'; + + @override + String toString() { + return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, totalSpan: ${_formatMS(totalSpan)})'; + } +} + /// States that an application can be in. /// /// The values below describe notifications from the operating system. @@ -781,6 +885,36 @@ class Window { _onDrawFrameZone = Zone.current; } + /// A callback that is invoked to report the [FrameTiming] of recently + /// rasterized frames. + /// + /// This can be used to see if the application has missed frames (through + /// [FrameTiming.buildDuration] and [FrameTiming.rasterDuration]), or high + /// latencies (through [FrameTiming.totalSpan]). + /// + /// Unlike [Timeline], the timing information here is available in the release + /// mode (additional to the profile and the debug mode). Hence this can be + /// used to monitor the application's performance in the wild. + /// + /// {@macro dart.ui.TimingsCallback.list} + /// + /// If this is null, no additional work will be done. If this is not null, + /// Flutter spends less than 0.1ms every 1 second to report the timings + /// (measured on iPhone6S). The 0.1ms is about 0.6% of 16ms (frame budget for + /// 60fps), or 0.01% CPU usage per second. + TimingsCallback get onReportTimings => _onReportTimings; + TimingsCallback _onReportTimings; + Zone _onReportTimingsZone; + set onReportTimings(TimingsCallback callback) { + if ((callback == null) != (_onReportTimings == null)) { + _setNeedsReportTimings(callback != null); + } + _onReportTimings = callback; + _onReportTimingsZone = Zone.current; + } + + void _setNeedsReportTimings(bool value) native 'Window_setNeedsReportTimings'; + /// A callback that is invoked when pointer data is available. /// /// The framework invokes this callback in the same zone in which the diff --git a/lib/ui/window/window.cc b/lib/ui/window/window.cc index b7691229612ae..64fb076daa67d 100644 --- a/lib/ui/window/window.cc +++ b/lib/ui/window/window.cc @@ -60,6 +60,12 @@ void SetIsolateDebugName(Dart_NativeArguments args) { UIDartState::Current()->SetDebugName(name); } +void SetNeedsReportTimings(Dart_NativeArguments args) { + Dart_Handle exception = nullptr; + bool value = tonic::DartConverter::FromArguments(args, 1, exception); + UIDartState::Current()->window()->client()->SetNeedsReportTimings(value); +} + void ReportUnhandledException(Dart_NativeArguments args) { Dart_Handle exception = nullptr; @@ -320,6 +326,31 @@ void Window::BeginFrame(fml::TimePoint frameTime) { tonic::LogIfError(tonic::DartInvokeField(library_.value(), "_drawFrame", {})); } +void Window::ReportTimings(std::vector timings) { + std::shared_ptr dart_state = library_.dart_state().lock(); + if (!dart_state) + return; + tonic::DartState::Scope scope(dart_state); + + Dart_Handle data_handle = + Dart_NewTypedData(Dart_TypedData_kInt64, timings.size()); + + Dart_TypedData_Type type; + void* data = nullptr; + intptr_t num_acquired = 0; + FML_CHECK(!Dart_IsError( + Dart_TypedDataAcquireData(data_handle, &type, &data, &num_acquired))); + FML_DCHECK(num_acquired == static_cast(timings.size())); + + memcpy(data, timings.data(), sizeof(int64_t) * timings.size()); + FML_CHECK(Dart_TypedDataReleaseData(data_handle)); + + tonic::LogIfError(tonic::DartInvokeField(library_.value(), "_reportTimings", + { + data_handle, + })); +} + void Window::CompletePlatformMessageEmptyResponse(int response_id) { if (!response_id) return; @@ -353,6 +384,7 @@ void Window::RegisterNatives(tonic::DartLibraryNatives* natives) { {"Window_updateSemantics", UpdateSemantics, 2, true}, {"Window_setIsolateDebugName", SetIsolateDebugName, 2, true}, {"Window_reportUnhandledException", ReportUnhandledException, 2, true}, + {"Window_setNeedsReportTimings", SetNeedsReportTimings, 2, true}, }); } diff --git a/lib/ui/window/window.h b/lib/ui/window/window.h index cb92bd1997396..99a8585a6910a 100644 --- a/lib/ui/window/window.h +++ b/lib/ui/window/window.h @@ -19,6 +19,16 @@ namespace tonic { class DartLibraryNatives; + +// So tonice::ToDart> returns List instead of +// List. +template <> +struct DartListFactory { + static Dart_Handle NewList(intptr_t length) { + return Dart_NewListOf(Dart_CoreType_Int, length); + } +}; + } // namespace tonic namespace flutter { @@ -46,6 +56,7 @@ class WindowClient { virtual FontCollection& GetFontCollection() = 0; virtual void UpdateIsolateDescription(const std::string isolate_name, int64_t isolate_port) = 0; + virtual void SetNeedsReportTimings(bool value) = 0; protected: virtual ~WindowClient(); @@ -74,6 +85,7 @@ class Window final { SemanticsAction action, std::vector args); void BeginFrame(fml::TimePoint frameTime); + void ReportTimings(std::vector timings); void CompletePlatformMessageResponse(int response_id, std::vector data); diff --git a/runtime/runtime_controller.cc b/runtime/runtime_controller.cc index 62c717e0c2779..c0d9c3efda892 100644 --- a/runtime/runtime_controller.cc +++ b/runtime/runtime_controller.cc @@ -231,6 +231,14 @@ bool RuntimeController::BeginFrame(fml::TimePoint frame_time) { return false; } +bool RuntimeController::ReportTimings(std::vector timings) { + if (auto* window = GetWindowIfAvailable()) { + window->ReportTimings(std::move(timings)); + return true; + } + return false; +} + bool RuntimeController::NotifyIdle(int64_t deadline) { std::shared_ptr root_isolate = root_isolate_.lock(); if (!root_isolate) { @@ -320,6 +328,10 @@ void RuntimeController::UpdateIsolateDescription(const std::string isolate_name, client_.UpdateIsolateDescription(isolate_name, isolate_port); } +void RuntimeController::SetNeedsReportTimings(bool value) { + client_.SetNeedsReportTimings(value); +} + Dart_Port RuntimeController::GetMainPort() { std::shared_ptr root_isolate = root_isolate_.lock(); return root_isolate ? root_isolate->main_port() : ILLEGAL_PORT; diff --git a/runtime/runtime_controller.h b/runtime/runtime_controller.h index 8522b35d2ff76..5a125013ea484 100644 --- a/runtime/runtime_controller.h +++ b/runtime/runtime_controller.h @@ -59,6 +59,8 @@ class RuntimeController final : public WindowClient { bool BeginFrame(fml::TimePoint frame_time); + bool ReportTimings(std::vector timings); + bool NotifyIdle(int64_t deadline); bool IsRootIsolateRunning() const; @@ -177,6 +179,9 @@ class RuntimeController final : public WindowClient { void UpdateIsolateDescription(const std::string isolate_name, int64_t isolate_port) override; + // |WindowClient| + void SetNeedsReportTimings(bool value) override; + FML_DISALLOW_COPY_AND_ASSIGN(RuntimeController); }; diff --git a/runtime/runtime_delegate.h b/runtime/runtime_delegate.h index 8dd69dbefb6c6..189d764b1eb5b 100644 --- a/runtime/runtime_delegate.h +++ b/runtime/runtime_delegate.h @@ -35,6 +35,8 @@ class RuntimeDelegate { virtual void UpdateIsolateDescription(const std::string isolate_name, int64_t isolate_port) = 0; + virtual void SetNeedsReportTimings(bool value) = 0; + protected: virtual ~RuntimeDelegate(); }; diff --git a/shell/common/BUILD.gn b/shell/common/BUILD.gn index 53deba81b5241..dbf0ee942c908 100644 --- a/shell/common/BUILD.gn +++ b/shell/common/BUILD.gn @@ -161,6 +161,7 @@ shell_host_executable("shell_unittests") { ":shell_unittests_fixtures", ":shell_unittests_gpu_configuration", "$flutter_root/common", + "$flutter_root/flow", "$flutter_root/shell", "$flutter_root/testing:dart", ] diff --git a/shell/common/animator.cc b/shell/common/animator.cc index 2defe146a8666..3632476ff6a1b 100644 --- a/shell/common/animator.cc +++ b/shell/common/animator.cc @@ -173,8 +173,7 @@ void Animator::Render(std::unique_ptr layer_tree) { if (layer_tree) { // Note the frame time for instrumentation. - layer_tree->set_construction_time(fml::TimePoint::Now() - - last_begin_frame_time_); + layer_tree->RecordBuildTime(last_begin_frame_time_); } // Commit the pending continuation. diff --git a/shell/common/animator.h b/shell/common/animator.h index c5bd8b5b147e0..32c02f789fe0a 100644 --- a/shell/common/animator.h +++ b/shell/common/animator.h @@ -18,6 +18,10 @@ namespace flutter { +namespace testing { +class ShellTest; +} + class Animator final { public: class Delegate { @@ -87,6 +91,8 @@ class Animator final { fml::WeakPtrFactory weak_factory_; + friend class testing::ShellTest; + FML_DISALLOW_COPY_AND_ASSIGN(Animator); }; diff --git a/shell/common/engine.cc b/shell/common/engine.cc index c1043c3877550..3b38e577ab2c8 100644 --- a/shell/common/engine.cc +++ b/shell/common/engine.cc @@ -201,6 +201,11 @@ void Engine::BeginFrame(fml::TimePoint frame_time) { runtime_controller_->BeginFrame(frame_time); } +void Engine::ReportTimings(std::vector timings) { + TRACE_EVENT0("flutter", "Engine::ReportTimings"); + runtime_controller_->ReportTimings(std::move(timings)); +} + void Engine::NotifyIdle(int64_t deadline) { TRACE_EVENT1("flutter", "Engine::NotifyIdle", "deadline_now_delta", std::to_string(deadline - Dart_TimelineGetMicros()).c_str()); @@ -432,6 +437,10 @@ void Engine::UpdateIsolateDescription(const std::string isolate_name, delegate_.UpdateIsolateDescription(isolate_name, isolate_port); } +void Engine::SetNeedsReportTimings(bool value) { + delegate_.SetNeedsReportTimings(value); +} + FontCollection& Engine::GetFontCollection() { return font_collection_; } diff --git a/shell/common/engine.h b/shell/common/engine.h index e32ed11b65f6e..1a84f9f4216f3 100644 --- a/shell/common/engine.h +++ b/shell/common/engine.h @@ -52,6 +52,8 @@ class Engine final : public RuntimeDelegate { virtual void UpdateIsolateDescription(const std::string isolate_name, int64_t isolate_port) = 0; + + virtual void SetNeedsReportTimings(bool value) = 0; }; Engine(Delegate& delegate, @@ -84,6 +86,8 @@ class Engine final : public RuntimeDelegate { void BeginFrame(fml::TimePoint frame_time); + void ReportTimings(std::vector timings); + void NotifyIdle(int64_t deadline); Dart_Port GetUIIsolateMainPort(); @@ -150,6 +154,8 @@ class Engine final : public RuntimeDelegate { void UpdateIsolateDescription(const std::string isolate_name, int64_t isolate_port) override; + void SetNeedsReportTimings(bool value) override; + void StopAnimator(); void StartAnimatorIfPossible(); @@ -168,6 +174,8 @@ class Engine final : public RuntimeDelegate { RunStatus PrepareAndLaunchIsolate(RunConfiguration configuration); + friend class testing::ShellTest; + FML_DISALLOW_COPY_AND_ASSIGN(Engine); }; diff --git a/shell/common/fixtures/shell_test.dart b/shell/common/fixtures/shell_test.dart index 93b8b16ca9397..9dae97c1f1a37 100644 --- a/shell/common/fixtures/shell_test.dart +++ b/shell/common/fixtures/shell_test.dart @@ -3,9 +3,41 @@ // found in the LICENSE file. import 'dart:isolate'; +import 'dart:ui'; void main() {} +void nativeReportTimingsCallback(List timings) native 'NativeReportTimingsCallback'; +void nativeOnBeginFrame(int microseconds) native 'NativeOnBeginFrame'; + +@pragma('vm:entry-point') +void reportTimingsMain() { + window.onReportTimings = (List timings) { + List timestamps = []; + for (FrameTiming t in timings) { + for (FramePhase phase in FramePhase.values) { + timestamps.add(t.timestampInMicroseconds(phase)); + } + } + nativeReportTimingsCallback(timestamps); + }; +} + +@pragma('vm:entry-point') +void onBeginFrameMain() { + window.onBeginFrame = (Duration beginTime) { + nativeOnBeginFrame(beginTime.inMicroseconds); + }; +} + +@pragma('vm:entry-point') +void emptyMain() {} + +@pragma('vm:entry-point') +void dummyReportTimingsMain() { + window.onReportTimings = (List timings) {}; +} + @pragma('vm:entry-point') void fixturesAreFunctionalMain() { sayHiFromFixturesAreFunctionalMain(); diff --git a/shell/common/rasterizer.cc b/shell/common/rasterizer.cc index fd0296b1c4125..a348b21390fe0 100644 --- a/shell/common/rasterizer.cc +++ b/shell/common/rasterizer.cc @@ -22,14 +22,17 @@ namespace flutter { // used within this interval. static constexpr std::chrono::milliseconds kSkiaCleanupExpiration(15000); -Rasterizer::Rasterizer(TaskRunners task_runners) - : Rasterizer(std::move(task_runners), +Rasterizer::Rasterizer(Delegate& delegate, TaskRunners task_runners) + : Rasterizer(delegate, + std::move(task_runners), std::make_unique()) {} Rasterizer::Rasterizer( + Delegate& delegate, TaskRunners task_runners, std::unique_ptr compositor_context) - : task_runners_(std::move(task_runners)), + : delegate_(delegate), + task_runners_(std::move(task_runners)), compositor_context_(std::move(compositor_context)), weak_factory_(this) { FML_DCHECK(compositor_context_); @@ -151,6 +154,11 @@ void Rasterizer::DoDraw(std::unique_ptr layer_tree) { return; } + FrameTiming timing; + timing.Set(FrameTiming::kBuildStart, layer_tree->build_start()); + timing.Set(FrameTiming::kBuildFinish, layer_tree->build_finish()); + timing.Set(FrameTiming::kRasterStart, fml::TimePoint::Now()); + PersistentCache* persistent_cache = PersistentCache::GetCacheForProcess(); persistent_cache->ResetStoredNewShaders(); @@ -164,6 +172,12 @@ void Rasterizer::DoDraw(std::unique_ptr layer_tree) { ScreenshotLastLayerTree(ScreenshotType::SkiaPicture, false); persistent_cache->DumpSkp(*screenshot.data); } + + // TODO(liyuqian): in Fuchsia, the rasterization doesn't finish when + // Rasterizer::DoDraw finishes. Future work is needed to adapt the timestamp + // for Fuchsia to capture SceneUpdateContext::ExecutePaintTasks. + timing.Set(FrameTiming::kRasterFinish, fml::TimePoint::Now()); + delegate_.OnFrameRasterized(timing); } bool Rasterizer::DrawToSurface(flutter::LayerTree& layer_tree) { @@ -178,7 +192,7 @@ bool Rasterizer::DrawToSurface(flutter::LayerTree& layer_tree) { // There is no way for the compositor to know how long the layer tree // construction took. Fortunately, the layer tree does. Grab that time // for instrumentation. - compositor_context_->ui_time().SetLapTime(layer_tree.construction_time()); + compositor_context_->ui_time().SetLapTime(layer_tree.build_time()); auto* canvas = frame->SkiaCanvas(); diff --git a/shell/common/rasterizer.h b/shell/common/rasterizer.h index a34e511d51cc0..7d525816da73a 100644 --- a/shell/common/rasterizer.h +++ b/shell/common/rasterizer.h @@ -7,6 +7,7 @@ #include +#include "flutter/common/settings.h" #include "flutter/common/task_runners.h" #include "flutter/flow/compositor_context.h" #include "flutter/flow/layers/layer_tree.h" @@ -21,9 +22,14 @@ namespace flutter { class Rasterizer final : public SnapshotDelegate { public: - Rasterizer(TaskRunners task_runners); + class Delegate { + public: + virtual void OnFrameRasterized(const FrameTiming&) = 0; + }; + Rasterizer(Delegate& delegate, TaskRunners task_runners); - Rasterizer(TaskRunners task_runners, + Rasterizer(Delegate& delegate, + TaskRunners task_runners, std::unique_ptr compositor_context); ~Rasterizer(); @@ -76,6 +82,7 @@ class Rasterizer final : public SnapshotDelegate { void SetResourceCacheMaxBytes(int max_bytes); private: + Delegate& delegate_; TaskRunners task_runners_; std::unique_ptr surface_; std::unique_ptr compositor_context_; diff --git a/shell/common/shell.cc b/shell/common/shell.cc index 7bb1b6ce8bd14..e050609d31882 100644 --- a/shell/common/shell.cc +++ b/shell/common/shell.cc @@ -277,7 +277,8 @@ std::unique_ptr Shell::Create( Shell::Shell(DartVMRef vm, TaskRunners task_runners, Settings settings) : task_runners_(std::move(task_runners)), settings_(std::move(settings)), - vm_(std::move(vm)) { + vm_(std::move(vm)), + weak_factory_(this) { FML_CHECK(vm_) << "Must have access to VM to create a shell."; FML_DCHECK(task_runners_.IsValid()); FML_DCHECK(task_runners_.GetPlatformTaskRunner()->RunsTasksOnCurrentThread()); @@ -389,6 +390,13 @@ bool Shell::Setup(std::unique_ptr platform_view, rasterizer_ = std::move(rasterizer); io_manager_ = std::move(io_manager); + // The weak ptr must be generated in the platform thread which owns the unique + // ptr. + // + // TODO(liyuqian): make weak_rasterizer_ and weak_platform_view_ and use + // them in the getters. + weak_engine_ = engine_->GetWeakPtr(); + is_setup_ = true; vm_->GetServiceProtocol()->AddHandler(this, GetServiceProtocolDescription()); @@ -417,7 +425,7 @@ fml::WeakPtr Shell::GetRasterizer() { fml::WeakPtr Shell::GetEngine() { FML_DCHECK(is_setup_); - return engine_->GetWeakPtr(); + return weak_engine_; } fml::WeakPtr Shell::GetPlatformView() { @@ -876,6 +884,77 @@ void Shell::UpdateIsolateDescription(const std::string isolate_name, vm_->GetServiceProtocol()->SetHandlerDescription(this, description); } +void Shell::SetNeedsReportTimings(bool value) { + needs_report_timings_ = value; +} + +void Shell::ReportTimings() { + FML_DCHECK(is_setup_); + FML_DCHECK(task_runners_.GetGPUTaskRunner()->RunsTasksOnCurrentThread()); + + auto timings = std::move(unreported_timings_); + unreported_timings_ = {}; + task_runners_.GetUITaskRunner()->PostTask([timings, engine = GetEngine()] { + if (engine) { + engine->ReportTimings(std::move(timings)); + } + }); +} + +size_t Shell::UnreportedFramesCount() const { + // Check that this is running on the GPU thread to avoid race conditions. + FML_DCHECK(task_runners_.GetGPUTaskRunner()->RunsTasksOnCurrentThread()); + FML_DCHECK(unreported_timings_.size() % FrameTiming::kCount == 0); + return unreported_timings_.size() / FrameTiming::kCount; +} + +void Shell::OnFrameRasterized(const FrameTiming& timing) { + FML_DCHECK(is_setup_); + FML_DCHECK(task_runners_.GetGPUTaskRunner()->RunsTasksOnCurrentThread()); + + // The C++ callback defined in settings.h and set by Flutter runner. This is + // independent of the timings report to the Dart side. + if (settings_.frame_rasterized_callback) { + settings_.frame_rasterized_callback(timing); + } + + if (!needs_report_timings_) { + return; + } + + for (auto phase : FrameTiming::kPhases) { + unreported_timings_.push_back( + timing.Get(phase).ToEpochDelta().ToMicroseconds()); + } + + // In tests using iPhone 6S with profile mode, sending a batch of 1 frame or a + // batch of 100 frames have roughly the same cost of less than 0.1ms. Sending + // a batch of 500 frames costs about 0.2ms. The 1 second threshold usually + // kicks in before we reaching the following 100 frames threshold. The 100 + // threshold here is mainly for unit tests (so we don't have to write a + // 1-second unit test), and make sure that our vector won't grow too big with + // future 120fps, 240fps, or 1000fps displays. + if (UnreportedFramesCount() >= 100) { + ReportTimings(); + } else if (!frame_timings_report_scheduled_) { + // Also make sure that frame times get reported with a max latency of 1 + // second. Otherwise, the timings of last few frames of an animation may + // never be reported until the next animation starts. + frame_timings_report_scheduled_ = true; + task_runners_.GetGPUTaskRunner()->PostDelayedTask( + [self = weak_factory_.GetWeakPtr()]() { + if (!self.get()) { + return; + } + self->frame_timings_report_scheduled_ = false; + if (self->UnreportedFramesCount() > 0) { + self->ReportTimings(); + } + }, + fml::TimeDelta::FromSeconds(1)); + } +} + // |ServiceProtocol::Handler| fml::RefPtr Shell::GetServiceProtocolHandlerTaskRunner( fml::StringView method) const { diff --git a/shell/common/shell.h b/shell/common/shell.h index 948afb1e31891..a226761ff2ef1 100644 --- a/shell/common/shell.h +++ b/shell/common/shell.h @@ -37,6 +37,7 @@ namespace flutter { class Shell final : public PlatformView::Delegate, public Animator::Delegate, public Engine::Delegate, + public Rasterizer::Delegate, public ServiceProtocol::Handler { public: template @@ -93,6 +94,8 @@ class Shell final : public PlatformView::Delegate, std::unique_ptr rasterizer_; // on GPU task runner std::unique_ptr io_manager_; // on IO task runner + fml::WeakPtr weak_engine_; // to be shared across threads + std::unordered_map, ServiceProtocolHandler> // task-runner/function @@ -102,6 +105,22 @@ class Shell final : public PlatformView::Delegate, bool is_setup_ = false; uint64_t next_pointer_flow_id_ = 0; + // Written in the UI thread and read from the GPU thread. Hence make it + // atomic. + std::atomic needs_report_timings_{false}; + + // Whether there's a task scheduled to report the timings to Dart through + // ui.Window.onReportTimings. + bool frame_timings_report_scheduled_ = false; + + // Vector of FrameTiming::kCount * n timestamps for n frames whose timings + // have not been reported yet. Vector of ints instead of FrameTiming is stored + // here for easier conversions to Dart objects. + std::vector unreported_timings_; + + // How many frames have been timed since last report. + size_t UnreportedFramesCount() const; + Shell(TaskRunners task_runners, Settings settings); Shell(DartVMRef vm, TaskRunners task_runners, Settings settings); @@ -119,6 +138,8 @@ class Shell final : public PlatformView::Delegate, std::unique_ptr rasterizer, std::unique_ptr io_manager); + void ReportTimings(); + // |PlatformView::Delegate| void OnPlatformViewCreated(std::unique_ptr surface) override; @@ -193,6 +214,12 @@ class Shell final : public PlatformView::Delegate, void UpdateIsolateDescription(const std::string isolate_name, int64_t isolate_port) override; + // |Engine::Delegate| + void SetNeedsReportTimings(bool value) override; + + // |Rasterizer::Delegate| + void OnFrameRasterized(const FrameTiming&) override; + // |ServiceProtocol::Handler| fml::RefPtr GetServiceProtocolHandlerTaskRunner( fml::StringView method) const override; @@ -237,6 +264,10 @@ class Shell final : public PlatformView::Delegate, const ServiceProtocol::Handler::ServiceProtocolMap& params, rapidjson::Document& response); + fml::WeakPtrFactory weak_factory_; + + friend class testing::ShellTest; + FML_DISALLOW_COPY_AND_ASSIGN(Shell); }; diff --git a/shell/common/shell_benchmarks.cc b/shell/common/shell_benchmarks.cc index dd344abd54568..c101cd3a4fb56 100644 --- a/shell/common/shell_benchmarks.cc +++ b/shell/common/shell_benchmarks.cc @@ -38,7 +38,7 @@ static void StartupAndShutdownShell(benchmark::State& state, return std::make_unique(shell, shell.GetTaskRunners()); }, [](Shell& shell) { - return std::make_unique(shell.GetTaskRunners()); + return std::make_unique(shell, shell.GetTaskRunners()); }); } diff --git a/shell/common/shell_test.cc b/shell/common/shell_test.cc index 54bbd9d18f79e..152c05b1e3f56 100644 --- a/shell/common/shell_test.cc +++ b/shell/common/shell_test.cc @@ -6,6 +6,9 @@ #include "flutter/shell/common/shell_test.h" +#include "flutter/flow/layers/layer_tree.h" +#include "flutter/flow/layers/transform_layer.h" +#include "flutter/fml/make_copyable.h" #include "flutter/fml/mapping.h" #include "flutter/runtime/dart_vm.h" #include "flutter/testing/testing.h" @@ -58,6 +61,69 @@ void ShellTest::SetSnapshotsAndAssets(Settings& settings) { } } +void ShellTest::PlatformViewNotifyCreated(Shell* shell) { + fml::AutoResetWaitableEvent latch; + fml::TaskRunner::RunNowOrPostTask( + shell->GetTaskRunners().GetPlatformTaskRunner(), [shell, &latch]() { + shell->GetPlatformView()->NotifyCreated(); + latch.Signal(); + }); + latch.Wait(); +} + +void ShellTest::RunEngine(Shell* shell, RunConfiguration configuration) { + fml::AutoResetWaitableEvent latch; + fml::TaskRunner::RunNowOrPostTask( + shell->GetTaskRunners().GetUITaskRunner(), + fml::MakeCopyable([&latch, config = std::move(configuration), + engine = shell->GetEngine()]() mutable { + ASSERT_TRUE(engine); + ASSERT_EQ(engine->Run(std::move(config)), Engine::RunStatus::Success); + latch.Signal(); + })); + latch.Wait(); +} + +void ShellTest::PumpOneFrame(Shell* shell) { + // Set viewport to nonempty, and call Animator::BeginFrame to make the layer + // tree pipeline nonempty. Without either of this, the layer tree below + // won't be rasterized. + fml::AutoResetWaitableEvent latch; + shell->GetTaskRunners().GetUITaskRunner()->PostTask( + [&latch, engine = shell->GetEngine()]() { + engine->SetViewportMetrics({1, 1, 1, 0, 0, 0, 0, 0, 0, 0, 0}); + engine->animator_->BeginFrame(fml::TimePoint::Now(), + fml::TimePoint::Now()); + latch.Signal(); + }); + latch.Wait(); + + latch.Reset(); + // Call |Render| to rasterize a layer tree and trigger |OnFrameRasterized| + fml::WeakPtr runtime_delegate = shell->GetEngine(); + shell->GetTaskRunners().GetUITaskRunner()->PostTask( + [&latch, runtime_delegate]() { + auto layer_tree = std::make_unique(); + auto root_layer = std::make_shared(); + layer_tree->set_root_layer(root_layer); + runtime_delegate->Render(std::move(layer_tree)); + latch.Signal(); + }); + latch.Wait(); +} + +int ShellTest::UnreportedTimingsCount(Shell* shell) { + return shell->unreported_timings_.size(); +} + +void ShellTest::SetNeedsReportTimings(Shell* shell, bool value) { + shell->SetNeedsReportTimings(value); +} + +bool ShellTest::GetNeedsReportTimings(Shell* shell) { + return shell->needs_report_timings_; +} + Settings ShellTest::CreateSettingsForFixture() { Settings settings; settings.leak_vm = false; @@ -84,6 +150,23 @@ TaskRunners ShellTest::GetTaskRunnersForFixture() { }; } +std::unique_ptr ShellTest::CreateShell(Settings settings) { + return CreateShell(std::move(settings), GetTaskRunnersForFixture()); +} + +std::unique_ptr ShellTest::CreateShell(Settings settings, + TaskRunners task_runners) { + return Shell::Create( + task_runners, settings, + [](Shell& shell) { + return std::make_unique(shell, + shell.GetTaskRunners()); + }, + [](Shell& shell) { + return std::make_unique(shell, shell.GetTaskRunners()); + }); +} + // |testing::ThreadTest| void ShellTest::SetUp() { ThreadTest::SetUp(); diff --git a/shell/common/shell_test.h b/shell/common/shell_test.h index e011cb6e9d237..2a839b821e6e1 100644 --- a/shell/common/shell_test.h +++ b/shell/common/shell_test.h @@ -26,11 +26,31 @@ class ShellTest : public ThreadTest { ~ShellTest(); Settings CreateSettingsForFixture(); - + std::unique_ptr CreateShell(Settings settings); + std::unique_ptr CreateShell(Settings settings, + TaskRunners task_runners); TaskRunners GetTaskRunnersForFixture(); void AddNativeCallback(std::string name, Dart_NativeFunction callback); + static void PlatformViewNotifyCreated( + Shell* shell); // This creates the surface + static void RunEngine(Shell* shell, RunConfiguration configuration); + + static void PumpOneFrame(Shell* shell); + + // Declare |UnreportedTimingsCount|, |GetNeedsReportTimings| and + // |SetNeedsReportTimings| inside |ShellTest| mainly for easier friend class + // declarations as shell unit tests and Shell are in different name spaces. + + static bool GetNeedsReportTimings(Shell* shell); + static void SetNeedsReportTimings(Shell* shell, bool value); + + // Do not assert |UnreportedTimingsCount| to be positive in any tests. + // Otherwise those tests will be flaky as the clearing of unreported timings + // is unpredictive. + static int UnreportedTimingsCount(Shell* shell); + protected: // |testing::ThreadTest| void SetUp() override; diff --git a/shell/common/shell_unittests.cc b/shell/common/shell_unittests.cc index feabf2cfd816f..79143368cb2be 100644 --- a/shell/common/shell_unittests.cc +++ b/shell/common/shell_unittests.cc @@ -8,6 +8,8 @@ #include #include +#include "flutter/flow/layers/layer_tree.h" +#include "flutter/flow/layers/transform_layer.h" #include "flutter/fml/command_line.h" #include "flutter/fml/make_copyable.h" #include "flutter/fml/message_loop.h" @@ -32,15 +34,7 @@ static bool ValidateShell(Shell* shell) { return false; } - { - fml::AutoResetWaitableEvent latch; - fml::TaskRunner::RunNowOrPostTask( - shell->GetTaskRunners().GetPlatformTaskRunner(), [shell, &latch]() { - shell->GetPlatformView()->NotifyCreated(); - latch.Signal(); - }); - latch.Wait(); - } + ShellTest::PlatformViewNotifyCreated(shell); { fml::AutoResetWaitableEvent latch; @@ -59,15 +53,7 @@ TEST_F(ShellTest, InitializeWithInvalidThreads) { ASSERT_FALSE(DartVMRef::IsInstanceRunning()); Settings settings = CreateSettingsForFixture(); TaskRunners task_runners("test", nullptr, nullptr, nullptr, nullptr); - auto shell = Shell::Create( - std::move(task_runners), settings, - [](Shell& shell) { - return std::make_unique(shell, - shell.GetTaskRunners()); - }, - [](Shell& shell) { - return std::make_unique(shell.GetTaskRunners()); - }); + auto shell = CreateShell(std::move(settings), std::move(task_runners)); ASSERT_FALSE(shell); ASSERT_FALSE(DartVMRef::IsInstanceRunning()); } @@ -82,15 +68,7 @@ TEST_F(ShellTest, InitializeWithDifferentThreads) { thread_host.gpu_thread->GetTaskRunner(), thread_host.ui_thread->GetTaskRunner(), thread_host.io_thread->GetTaskRunner()); - auto shell = Shell::Create( - std::move(task_runners), settings, - [](Shell& shell) { - return std::make_unique(shell, - shell.GetTaskRunners()); - }, - [](Shell& shell) { - return std::make_unique(shell.GetTaskRunners()); - }); + auto shell = CreateShell(std::move(settings), std::move(task_runners)); ASSERT_TRUE(ValidateShell(shell.get())); ASSERT_TRUE(DartVMRef::IsInstanceRunning()); shell.reset(); @@ -105,15 +83,7 @@ TEST_F(ShellTest, InitializeWithSingleThread) { auto task_runner = thread_host.platform_thread->GetTaskRunner(); TaskRunners task_runners("test", task_runner, task_runner, task_runner, task_runner); - auto shell = Shell::Create( - std::move(task_runners), settings, - [](Shell& shell) { - return std::make_unique(shell, - shell.GetTaskRunners()); - }, - [](Shell& shell) { - return std::make_unique(shell.GetTaskRunners()); - }); + auto shell = CreateShell(std::move(settings), std::move(task_runners)); ASSERT_TRUE(DartVMRef::IsInstanceRunning()); ASSERT_TRUE(ValidateShell(shell.get())); shell.reset(); @@ -127,15 +97,7 @@ TEST_F(ShellTest, InitializeWithSingleThreadWhichIsTheCallingThread) { auto task_runner = fml::MessageLoop::GetCurrent().GetTaskRunner(); TaskRunners task_runners("test", task_runner, task_runner, task_runner, task_runner); - auto shell = Shell::Create( - std::move(task_runners), settings, - [](Shell& shell) { - return std::make_unique(shell, - shell.GetTaskRunners()); - }, - [](Shell& shell) { - return std::make_unique(shell.GetTaskRunners()); - }); + auto shell = CreateShell(std::move(settings), std::move(task_runners)); ASSERT_TRUE(ValidateShell(shell.get())); ASSERT_TRUE(DartVMRef::IsInstanceRunning()); shell.reset(); @@ -162,7 +124,7 @@ TEST_F(ShellTest, shell.GetTaskRunners()); }, [](Shell& shell) { - return std::make_unique(shell.GetTaskRunners()); + return std::make_unique(shell, shell.GetTaskRunners()); }); ASSERT_TRUE(ValidateShell(shell.get())); ASSERT_TRUE(DartVMRef::IsInstanceRunning()); @@ -183,15 +145,7 @@ TEST_F(ShellTest, InitializeWithGPUAndPlatformThreadsTheSame) { thread_host.ui_thread->GetTaskRunner(), // ui thread_host.io_thread->GetTaskRunner() // io ); - auto shell = Shell::Create( - std::move(task_runners), settings, - [](Shell& shell) { - return std::make_unique(shell, - shell.GetTaskRunners()); - }, - [](Shell& shell) { - return std::make_unique(shell.GetTaskRunners()); - }); + auto shell = CreateShell(std::move(settings), std::move(task_runners)); ASSERT_TRUE(DartVMRef::IsInstanceRunning()); ASSERT_TRUE(ValidateShell(shell.get())); shell.reset(); @@ -200,16 +154,8 @@ TEST_F(ShellTest, InitializeWithGPUAndPlatformThreadsTheSame) { TEST_F(ShellTest, FixturesAreFunctional) { ASSERT_FALSE(DartVMRef::IsInstanceRunning()); - const auto settings = CreateSettingsForFixture(); - auto shell = Shell::Create( - GetTaskRunnersForFixture(), settings, - [](Shell& shell) { - return std::make_unique(shell, - shell.GetTaskRunners()); - }, - [](Shell& shell) { - return std::make_unique(shell.GetTaskRunners()); - }); + auto settings = CreateSettingsForFixture(); + auto shell = CreateShell(std::move(settings)); ASSERT_TRUE(ValidateShell(shell.get())); auto configuration = RunConfiguration::InferFromSettings(settings); @@ -221,17 +167,7 @@ TEST_F(ShellTest, FixturesAreFunctional) { "SayHiFromFixturesAreFunctionalMain", CREATE_NATIVE_ENTRY([&main_latch](auto args) { main_latch.Signal(); })); - fml::AutoResetWaitableEvent latch; - fml::TaskRunner::RunNowOrPostTask( - shell->GetTaskRunners().GetUITaskRunner(), - fml::MakeCopyable([&latch, config = std::move(configuration), - engine = shell->GetEngine()]() mutable { - ASSERT_TRUE(engine); - ASSERT_EQ(engine->Run(std::move(config)), Engine::RunStatus::Success); - latch.Signal(); - })); - - latch.Wait(); + RunEngine(shell.get(), std::move(configuration)); main_latch.Wait(); ASSERT_TRUE(DartVMRef::IsInstanceRunning()); shell.reset(); @@ -240,16 +176,8 @@ TEST_F(ShellTest, FixturesAreFunctional) { TEST_F(ShellTest, SecondaryIsolateBindingsAreSetupViaShellSettings) { ASSERT_FALSE(DartVMRef::IsInstanceRunning()); - const auto settings = CreateSettingsForFixture(); - auto shell = Shell::Create( - GetTaskRunnersForFixture(), settings, - [](Shell& shell) { - return std::make_unique(shell, - shell.GetTaskRunners()); - }, - [](Shell& shell) { - return std::make_unique(shell.GetTaskRunners()); - }); + auto settings = CreateSettingsForFixture(); + auto shell = CreateShell(std::move(settings)); ASSERT_TRUE(ValidateShell(shell.get())); auto configuration = RunConfiguration::InferFromSettings(settings); @@ -261,13 +189,7 @@ TEST_F(ShellTest, SecondaryIsolateBindingsAreSetupViaShellSettings) { latch.CountDown(); })); - fml::TaskRunner::RunNowOrPostTask( - shell->GetTaskRunners().GetUITaskRunner(), - fml::MakeCopyable([config = std::move(configuration), - engine = shell->GetEngine()]() mutable { - ASSERT_TRUE(engine); - ASSERT_EQ(engine->Run(std::move(config)), Engine::RunStatus::Success); - })); + RunEngine(shell.get(), std::move(configuration)); latch.Wait(); @@ -313,5 +235,188 @@ TEST_F(ShellTest, WhitelistedDartVMFlag) { #endif } +TEST_F(ShellTest, NoNeedToReportTimingsByDefault) { + auto settings = CreateSettingsForFixture(); + std::unique_ptr shell = CreateShell(std::move(settings)); + + // Create the surface needed by rasterizer + PlatformViewNotifyCreated(shell.get()); + + auto configuration = RunConfiguration::InferFromSettings(settings); + configuration.SetEntrypoint("emptyMain"); + + RunEngine(shell.get(), std::move(configuration)); + PumpOneFrame(shell.get()); + ASSERT_FALSE(GetNeedsReportTimings(shell.get())); + + // This assertion may or may not be the direct result of needs_report_timings_ + // being false. The count could be 0 simply because we just cleared unreported + // timings by reporting them. Hence this can't replace the + // ASSERT_FALSE(GetNeedsReportTimings(shell.get())) check. We added this + // assertion for an additional confidence that we're not pushing back to + // unreported timings unnecessarily. + // + // Conversely, do not assert UnreportedTimingsCount(shell.get()) to be + // positive in any tests. Otherwise those tests will be flaky as the clearing + // of unreported timings is unpredictive. + ASSERT_EQ(UnreportedTimingsCount(shell.get()), 0); +} + +TEST_F(ShellTest, NeedsReportTimingsIsSetWithCallback) { + auto settings = CreateSettingsForFixture(); + std::unique_ptr shell = CreateShell(std::move(settings)); + + // Create the surface needed by rasterizer + PlatformViewNotifyCreated(shell.get()); + + auto configuration = RunConfiguration::InferFromSettings(settings); + configuration.SetEntrypoint("dummyReportTimingsMain"); + + RunEngine(shell.get(), std::move(configuration)); + PumpOneFrame(shell.get()); + ASSERT_TRUE(GetNeedsReportTimings(shell.get())); +} + +static void CheckFrameTimings(const std::vector& timings, + fml::TimePoint start, + fml::TimePoint finish) { + fml::TimePoint last_frame_start; + for (size_t i = 0; i < timings.size(); i += 1) { + // Ensure that timings are sorted. + ASSERT_TRUE(timings[i].Get(FrameTiming::kPhases[0]) >= last_frame_start); + last_frame_start = timings[i].Get(FrameTiming::kPhases[0]); + + fml::TimePoint last_phase_time; + for (auto phase : FrameTiming::kPhases) { + ASSERT_TRUE(timings[i].Get(phase) >= start); + ASSERT_TRUE(timings[i].Get(phase) <= finish); + + // phases should have weakly increasing time points + ASSERT_TRUE(last_phase_time <= timings[i].Get(phase)); + last_phase_time = timings[i].Get(phase); + } + } +} + +TEST_F(ShellTest, ReportTimingsIsCalled) { + fml::TimePoint start = fml::TimePoint::Now(); + auto settings = CreateSettingsForFixture(); + std::unique_ptr shell = CreateShell(std::move(settings)); + + // Create the surface needed by rasterizer + PlatformViewNotifyCreated(shell.get()); + + auto configuration = RunConfiguration::InferFromSettings(settings); + ASSERT_TRUE(configuration.IsValid()); + configuration.SetEntrypoint("reportTimingsMain"); + fml::AutoResetWaitableEvent reportLatch; + std::vector timestamps; + auto nativeTimingCallback = [&reportLatch, + ×tamps](Dart_NativeArguments args) { + Dart_Handle exception = nullptr; + timestamps = tonic::DartConverter>::FromArguments( + args, 0, exception); + reportLatch.Signal(); + }; + AddNativeCallback("NativeReportTimingsCallback", + CREATE_NATIVE_ENTRY(nativeTimingCallback)); + RunEngine(shell.get(), std::move(configuration)); + + // Pump many frames so we can trigger the report quickly instead of waiting + // for the 1 second threshold. + for (int i = 0; i < 200; i += 1) { + PumpOneFrame(shell.get()); + } + + reportLatch.Wait(); + shell.reset(); + + fml::TimePoint finish = fml::TimePoint::Now(); + ASSERT_TRUE(timestamps.size() > 0); + ASSERT_TRUE(timestamps.size() % FrameTiming::kCount == 0); + std::vector timings(timestamps.size() / FrameTiming::kCount); + + for (size_t i = 0; i * FrameTiming::kCount < timestamps.size(); i += 1) { + for (auto phase : FrameTiming::kPhases) { + timings[i].Set( + phase, + fml::TimePoint::FromEpochDelta(fml::TimeDelta::FromMicroseconds( + timestamps[i * FrameTiming::kCount + phase]))); + } + } + CheckFrameTimings(timings, start, finish); +} + +TEST_F(ShellTest, FrameRasterizedCallbackIsCalled) { + fml::TimePoint start = fml::TimePoint::Now(); + + auto settings = CreateSettingsForFixture(); + fml::AutoResetWaitableEvent timingLatch; + FrameTiming timing; + + for (auto phase : FrameTiming::kPhases) { + timing.Set(phase, fml::TimePoint()); + // Check that the time points are initially smaller than start, so + // CheckFrameTimings will fail if they're not properly set later. + ASSERT_TRUE(timing.Get(phase) < start); + } + + settings.frame_rasterized_callback = [&timing, + &timingLatch](const FrameTiming& t) { + timing = t; + timingLatch.Signal(); + }; + + std::unique_ptr shell = CreateShell(std::move(settings)); + + // Create the surface needed by rasterizer + PlatformViewNotifyCreated(shell.get()); + + auto configuration = RunConfiguration::InferFromSettings(settings); + configuration.SetEntrypoint("onBeginFrameMain"); + + int64_t begin_frame; + auto nativeOnBeginFrame = [&begin_frame](Dart_NativeArguments args) { + Dart_Handle exception = nullptr; + begin_frame = + tonic::DartConverter::FromArguments(args, 0, exception); + }; + AddNativeCallback("NativeOnBeginFrame", + CREATE_NATIVE_ENTRY(nativeOnBeginFrame)); + + RunEngine(shell.get(), std::move(configuration)); + + PumpOneFrame(shell.get()); + + // Check that timing is properly set. This implies that + // settings.frame_rasterized_callback is called. + timingLatch.Wait(); + fml::TimePoint finish = fml::TimePoint::Now(); + std::vector timings = {timing}; + CheckFrameTimings(timings, start, finish); + + // Check that onBeginFrame has the same timestamp as FrameTiming's build start + int64_t build_start = + timing.Get(FrameTiming::kBuildStart).ToEpochDelta().ToMicroseconds(); + ASSERT_EQ(build_start, begin_frame); +} + +TEST(SettingsTest, FrameTimingSetsAndGetsProperly) { + // Ensure that all phases are in kPhases. + ASSERT_EQ(sizeof(FrameTiming::kPhases), + FrameTiming::kCount * sizeof(FrameTiming::Phase)); + + int lastPhaseIndex = -1; + FrameTiming timing; + for (auto phase : FrameTiming::kPhases) { + ASSERT_TRUE(phase > lastPhaseIndex); // Ensure that kPhases are in order. + lastPhaseIndex = phase; + auto fake_time = + fml::TimePoint::FromEpochDelta(fml::TimeDelta::FromMicroseconds(phase)); + timing.Set(phase, fake_time); + ASSERT_TRUE(timing.Get(phase) == fake_time); + } +} + } // namespace testing } // namespace flutter diff --git a/shell/platform/android/android_shell_holder.cc b/shell/platform/android/android_shell_holder.cc index 931d09b933fdc..e9b114fc42252 100644 --- a/shell/platform/android/android_shell_holder.cc +++ b/shell/platform/android/android_shell_holder.cc @@ -73,7 +73,7 @@ AndroidShellHolder::AndroidShellHolder( }; Shell::CreateCallback on_create_rasterizer = [](Shell& shell) { - return std::make_unique(shell.GetTaskRunners()); + return std::make_unique(shell, shell.GetTaskRunners()); }; // The current thread will be used as the platform thread. Ensure that the diff --git a/shell/platform/darwin/ios/framework/Source/FlutterEngine.mm b/shell/platform/darwin/ios/framework/Source/FlutterEngine.mm index f99c346ea1632..4ba2e83daa05b 100644 --- a/shell/platform/darwin/ios/framework/Source/FlutterEngine.mm +++ b/shell/platform/darwin/ios/framework/Source/FlutterEngine.mm @@ -353,7 +353,7 @@ - (BOOL)createShell:(NSString*)entrypoint libraryURI:(NSString*)libraryURI { flutter::Shell::CreateCallback on_create_rasterizer = [](flutter::Shell& shell) { - return std::make_unique(shell.GetTaskRunners()); + return std::make_unique(shell, shell.GetTaskRunners()); }; if (flutter::IsIosEmbeddedViewsPreviewEnabled()) { diff --git a/shell/platform/embedder/embedder.cc b/shell/platform/embedder/embedder.cc index 81e17127bdc5e..e49c08e1972bf 100644 --- a/shell/platform/embedder/embedder.cc +++ b/shell/platform/embedder/embedder.cc @@ -527,7 +527,8 @@ FlutterEngineResult FlutterEngineRun(size_t version, flutter::Shell::CreateCallback on_create_rasterizer = [](flutter::Shell& shell) { - return std::make_unique(shell.GetTaskRunners()); + return std::make_unique(shell, + shell.GetTaskRunners()); }; // TODO(chinmaygarde): This is the wrong spot for this. It belongs in the diff --git a/shell/testing/tester_main.cc b/shell/testing/tester_main.cc index fd729d1f434d2..e36ba8252ab47 100644 --- a/shell/testing/tester_main.cc +++ b/shell/testing/tester_main.cc @@ -106,7 +106,7 @@ int RunTester(const flutter::Settings& settings, bool run_forever) { }; Shell::CreateCallback on_create_rasterizer = [](Shell& shell) { - return std::make_unique(shell.GetTaskRunners()); + return std::make_unique(shell, shell.GetTaskRunners()); }; auto shell = Shell::Create(task_runners, // diff --git a/testing/dart/window_hooks_integration_test.dart b/testing/dart/window_hooks_integration_test.dart index d0ed135186390..1a6504d7749d5 100644 --- a/testing/dart/window_hooks_integration_test.dart +++ b/testing/dart/window_hooks_integration_test.dart @@ -36,6 +36,7 @@ void main() { VoidCallback originalOnLocaleChanged; FrameCallback originalOnBeginFrame; VoidCallback originalOnDrawFrame; + TimingsCallback originalOnReportTimings; PointerDataPacketCallback originalOnPointerDataPacket; VoidCallback originalOnSemanticsEnabledChanged; SemanticsActionCallback originalOnSemanticsAction; @@ -47,6 +48,7 @@ void main() { originalOnLocaleChanged = window.onLocaleChanged; originalOnBeginFrame = window.onBeginFrame; originalOnDrawFrame = window.onDrawFrame; + originalOnReportTimings = window.onReportTimings; originalOnPointerDataPacket = window.onPointerDataPacket; originalOnSemanticsEnabledChanged = window.onSemanticsEnabledChanged; originalOnSemanticsAction = window.onSemanticsAction; @@ -59,6 +61,7 @@ void main() { window.onLocaleChanged = originalOnLocaleChanged; window.onBeginFrame = originalOnBeginFrame; window.onDrawFrame = originalOnDrawFrame; + window.onReportTimings = originalOnReportTimings; window.onPointerDataPacket = originalOnPointerDataPacket; window.onSemanticsEnabledChanged = originalOnSemanticsEnabledChanged; window.onSemanticsAction = originalOnSemanticsAction; @@ -146,6 +149,22 @@ void main() { expect(runZone, same(innerZone)); }); + test('onReportTimings preserves callback zone', () { + Zone innerZone; + Zone runZone; + + runZoned(() { + innerZone = Zone.current; + window.onReportTimings = (List timings) { + runZone = Zone.current; + }; + }); + + _reportTimings([]); + expect(runZone, isNotNull); + expect(runZone, same(innerZone)); + }); + test('onPointerDataPacket preserves callback zone', () { Zone innerZone; Zone runZone; diff --git a/testing/dart/window_test.dart b/testing/dart/window_test.dart index 9b5c92b606ea7..6a4ed12bbcefc 100644 --- a/testing/dart/window_test.dart +++ b/testing/dart/window_test.dart @@ -19,4 +19,9 @@ void main() { })); }); }); + + test('FrameTiming.toString has the correct format', () { + FrameTiming timing = FrameTiming([1000, 8000, 9000, 19500]); + expect(timing.toString(), 'FrameTiming(buildDuration: 7.0ms, rasterDuration: 10.5ms, totalSpan: 18.5ms)'); + }); }