diff --git a/fml/time/time_delta.h b/fml/time/time_delta.h index 98a11b4100800..e54a1f8bf9bfa 100644 --- a/fml/time/time_delta.h +++ b/fml/time/time_delta.h @@ -55,6 +55,10 @@ class TimeDelta { return FromNanoseconds(seconds * (1000.0 * 1000.0 * 1000.0)); } + static constexpr TimeDelta FromMillisecondsF(double millis) { + return FromNanoseconds(millis * (1000.0 * 1000.0)); + } + constexpr int64_t ToNanoseconds() const { return delta_; } constexpr int64_t ToMicroseconds() const { return ToNanoseconds() / 1000; } constexpr int64_t ToMilliseconds() const { return ToMicroseconds() / 1000; } diff --git a/fml/trace_event.cc b/fml/trace_event.cc index 7e11b2c6f8e88..d055582d3a0eb 100644 --- a/fml/trace_event.cc +++ b/fml/trace_event.cc @@ -51,6 +51,7 @@ size_t TraceNonce() { void TraceTimelineEvent(TraceArg category_group, TraceArg name, + int64_t timestamp_micros, TraceIDArg identifier, Dart_Timeline_Event_Type type, const std::vector& c_names, @@ -66,7 +67,7 @@ void TraceTimelineEvent(TraceArg category_group, FlutterTimelineEvent( name, // label - Dart_TimelineGetMicros(), // timestamp0 + timestamp_micros, // timestamp0 identifier, // timestamp1_or_async_id type, // event type argument_count, // argument_count @@ -75,6 +76,22 @@ void TraceTimelineEvent(TraceArg category_group, ); } +void TraceTimelineEvent(TraceArg category_group, + TraceArg name, + TraceIDArg identifier, + Dart_Timeline_Event_Type type, + const std::vector& c_names, + const std::vector& values) { + TraceTimelineEvent(category_group, // group + name, // name + Dart_TimelineGetMicros(), // timestamp_micros + identifier, // identifier + type, // type + c_names, // names + values // values + ); +} + void TraceEvent0(TraceArg category_group, TraceArg name) { FlutterTimelineEvent(name, // label Dart_TimelineGetMicros(), // timestamp0 @@ -131,34 +148,6 @@ void TraceEventEnd(TraceArg name) { ); } -void TraceEventAsyncComplete(TraceArg category_group, - TraceArg name, - TimePoint begin, - TimePoint end) { - auto identifier = TraceNonce(); - - if (begin > end) { - std::swap(begin, end); - } - - FlutterTimelineEvent(name, // label - begin.ToEpochDelta().ToMicroseconds(), // timestamp0 - identifier, // timestamp1_or_async_id - Dart_Timeline_Event_Async_Begin, // event type - 0, // argument_count - nullptr, // argument_names - nullptr // argument_values - ); - FlutterTimelineEvent(name, // label - end.ToEpochDelta().ToMicroseconds(), // timestamp0 - identifier, // timestamp1_or_async_id - Dart_Timeline_Event_Async_End, // event type - 0, // argument_count - nullptr, // argument_names - nullptr // argument_values - ); -} - void TraceEventAsyncBegin0(TraceArg category_group, TraceArg name, TraceIDArg id) { @@ -275,6 +264,14 @@ size_t TraceNonce() { return 0; } +void TraceTimelineEvent(TraceArg category_group, + TraceArg name, + int64_t timestamp_micros, + TraceIDArg identifier, + Dart_Timeline_Event_Type type, + const std::vector& c_names, + const std::vector& values) {} + void TraceTimelineEvent(TraceArg category_group, TraceArg name, TraceIDArg identifier, diff --git a/fml/trace_event.h b/fml/trace_event.h index a90aed2ff643e..98d328e134819 100644 --- a/fml/trace_event.h +++ b/fml/trace_event.h @@ -114,6 +114,14 @@ using TraceIDArg = int64_t; void TraceSetWhitelist(const std::vector& whitelist); +void TraceTimelineEvent(TraceArg category_group, + TraceArg name, + int64_t timestamp_micros, + TraceIDArg id, + Dart_Timeline_Event_Type type, + const std::vector& names, + const std::vector& values); + void TraceTimelineEvent(TraceArg category_group, TraceArg name, TraceIDArg id, @@ -209,10 +217,40 @@ void TraceEvent2(TraceArg category_group, void TraceEventEnd(TraceArg name); +template void TraceEventAsyncComplete(TraceArg category_group, TraceArg name, TimePoint begin, - TimePoint end); + TimePoint end, + Args... args) { + auto identifier = TraceNonce(); + const auto split = SplitArguments(args...); + + if (begin > end) { + std::swap(begin, end); + } + + const int64_t begin_micros = begin.ToEpochDelta().ToMicroseconds(); + const int64_t end_micros = end.ToEpochDelta().ToMicroseconds(); + + TraceTimelineEvent(category_group, // group + name, // name + begin_micros, // timestamp_micros + identifier, // identifier + Dart_Timeline_Event_Async_Begin, // type + split.first, // names + split.second // values + ); + + TraceTimelineEvent(category_group, // group + name, // name + end_micros, // timestamp_micros + identifier, // identifier + Dart_Timeline_Event_Async_End, // type + split.first, // names + split.second // values + ); +} void TraceEventAsyncBegin0(TraceArg category_group, TraceArg name, diff --git a/shell/common/animator.h b/shell/common/animator.h index ba5e1f4df40a3..f96acb7e9a3a0 100644 --- a/shell/common/animator.h +++ b/shell/common/animator.h @@ -30,7 +30,7 @@ class Animator final { public: class Delegate { public: - virtual void OnAnimatorBeginFrame(fml::TimePoint frame_time) = 0; + virtual void OnAnimatorBeginFrame(fml::TimePoint frame_target_time) = 0; virtual void OnAnimatorNotifyIdle(int64_t deadline) = 0; diff --git a/shell/common/animator_unittests.cc b/shell/common/animator_unittests.cc index 3907cee3b89ab..ed54ea5272be2 100644 --- a/shell/common/animator_unittests.cc +++ b/shell/common/animator_unittests.cc @@ -84,10 +84,14 @@ TEST_F(ShellTest, VSyncTargetTime) { }); on_target_time_latch.Wait(); - ASSERT_EQ(ConstantFiringVsyncWaiter::frame_target_time.ToEpochDelta() - .ToMicroseconds(), + const auto vsync_waiter_target_time = + ConstantFiringVsyncWaiter::frame_target_time; + ASSERT_EQ(vsync_waiter_target_time.ToEpochDelta().ToMicroseconds(), target_time); + // validate that the latest target time has also been updated. + ASSERT_EQ(GetLatestFrameTargetTime(shell.get()), vsync_waiter_target_time); + // teardown. DestroyShell(std::move(shell), std::move(task_runners)); ASSERT_FALSE(DartVMRef::IsInstanceRunning()); diff --git a/shell/common/rasterizer.cc b/shell/common/rasterizer.cc index 4d7d5ea669b2f..0561b0ce4e4ee 100644 --- a/shell/common/rasterizer.cc +++ b/shell/common/rasterizer.cc @@ -8,6 +8,8 @@ #include +#include "fml/time/time_delta.h" +#include "fml/time/time_point.h" #include "third_party/skia/include/core/SkEncodedImageFormat.h" #include "third_party/skia/include/core/SkImageEncoder.h" #include "third_party/skia/include/core/SkPictureRecorder.h" @@ -240,6 +242,7 @@ RasterStatus Rasterizer::DoDraw( } FrameTiming timing; + const fml::TimePoint frame_target_time = layer_tree->target_time(); timing.Set(FrameTiming::kBuildStart, layer_tree->build_start()); timing.Set(FrameTiming::kBuildFinish, layer_tree->build_finish()); timing.Set(FrameTiming::kRasterStart, fml::TimePoint::Now()); @@ -265,9 +268,36 @@ RasterStatus Rasterizer::DoDraw( // 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()); + const auto raster_finish_time = fml::TimePoint::Now(); + timing.Set(FrameTiming::kRasterFinish, raster_finish_time); delegate_.OnFrameRasterized(timing); + if (raster_finish_time > frame_target_time) { + fml::TimePoint latest_frame_target_time = + delegate_.GetLatestFrameTargetTime(); + const auto frame_budget_millis = delegate_.GetFrameBudget().count(); + if (latest_frame_target_time < raster_finish_time) { + latest_frame_target_time = + latest_frame_target_time + + fml::TimeDelta::FromMillisecondsF(frame_budget_millis); + } + const auto frame_lag = + (latest_frame_target_time - frame_target_time).ToMillisecondsF(); + const int vsync_transitions_missed = round(frame_lag / frame_budget_millis); + fml::tracing::TraceEventAsyncComplete( + "flutter", // category + "SceneDisplayLag", // name + frame_target_time, // begin_time + raster_finish_time, // end_time + "frame_target_time", // arg_key_1 + frame_target_time, // arg_val_1 + "current_frame_target_time", // arg_key_2 + latest_frame_target_time, // arg_val_2 + "vsync_transitions_missed", // arg_key_3 + vsync_transitions_missed // arg_val_3 + ); + } + // Pipeline pressure is applied from a couple of places: // rasterizer: When there are more items as of the time of Consume. // animator (via shell): Frame gets produces every vsync. diff --git a/shell/common/rasterizer.h b/shell/common/rasterizer.h index f6bdd297ed8cc..d4d57c5efe117 100644 --- a/shell/common/rasterizer.h +++ b/shell/common/rasterizer.h @@ -19,6 +19,8 @@ #include "flutter/lib/ui/snapshot_delegate.h" #include "flutter/shell/common/pipeline.h" #include "flutter/shell/common/surface.h" +#include "fml/time/time_delta.h" +#include "fml/time/time_point.h" namespace flutter { @@ -67,6 +69,10 @@ class Rasterizer final : public SnapshotDelegate { /// Time limit for a smooth frame. See `Engine::GetDisplayRefreshRate`. virtual fml::Milliseconds GetFrameBudget() = 0; + + /// Target time for the latest frame. See also `Shell::OnAnimatorBeginFrame` + /// for when this time gets updated. + virtual fml::TimePoint GetLatestFrameTargetTime() const = 0; }; // TODO(dnfield): remove once embedders have caught up. @@ -75,6 +81,11 @@ class Rasterizer final : public SnapshotDelegate { fml::Milliseconds GetFrameBudget() override { return fml::kDefaultFrameBudget; } + // Returning a time in the past so we don't add additional trace + // events when exceeding the frame budget for other embedders. + fml::TimePoint GetLatestFrameTargetTime() const override { + return fml::TimePoint::FromEpochDelta(fml::TimeDelta::Zero()); + } }; //---------------------------------------------------------------------------- diff --git a/shell/common/shell.cc b/shell/common/shell.cc index 9125f8881b272..b0811e1769942 100644 --- a/shell/common/shell.cc +++ b/shell/common/shell.cc @@ -931,12 +931,17 @@ void Shell::OnPlatformViewSetNextFrameCallback(const fml::closure& closure) { } // |Animator::Delegate| -void Shell::OnAnimatorBeginFrame(fml::TimePoint frame_time) { +void Shell::OnAnimatorBeginFrame(fml::TimePoint frame_target_time) { FML_DCHECK(is_setup_); FML_DCHECK(task_runners_.GetUITaskRunner()->RunsTasksOnCurrentThread()); + // record the target time for use by rasterizer. + { + std::scoped_lock time_recorder_lock(time_recorder_mutex_); + latest_frame_target_time_.emplace(frame_target_time); + } if (engine_) { - engine_->BeginFrame(frame_time); + engine_->BeginFrame(frame_target_time); } } @@ -1165,6 +1170,13 @@ fml::Milliseconds Shell::GetFrameBudget() { } } +fml::TimePoint Shell::GetLatestFrameTargetTime() const { + std::scoped_lock time_recorder_lock(time_recorder_mutex_); + FML_CHECK(latest_frame_target_time_.has_value()) + << "GetLatestFrameTargetTime called before OnAnimatorBeginFrame"; + return latest_frame_target_time_.value(); +} + // |ServiceProtocol::Handler| fml::RefPtr Shell::GetServiceProtocolHandlerTaskRunner( std::string_view method) const { diff --git a/shell/common/shell.h b/shell/common/shell.h index d6345f115bde3..f8cbc85cd6c9a 100644 --- a/shell/common/shell.h +++ b/shell/common/shell.h @@ -6,6 +6,7 @@ #define SHELL_COMMON_SHELL_H_ #include +#include #include #include @@ -32,6 +33,7 @@ #include "flutter/shell/common/rasterizer.h" #include "flutter/shell/common/shell_io_manager.h" #include "flutter/shell/common/surface.h" +#include "fml/time/time_point.h" namespace flutter { @@ -368,6 +370,8 @@ class Shell final : public PlatformView::Delegate, const TaskRunners task_runners_; const Settings settings_; DartVMRef vm_; + mutable std::mutex time_recorder_mutex_; + std::optional latest_frame_target_time_; std::unique_ptr platform_view_; // on platform task runner std::unique_ptr engine_; // on UI task runner std::unique_ptr rasterizer_; // on GPU task runner @@ -478,7 +482,7 @@ class Shell final : public PlatformView::Delegate, void OnPlatformViewSetNextFrameCallback(const fml::closure& closure) override; // |Animator::Delegate| - void OnAnimatorBeginFrame(fml::TimePoint frame_time) override; + void OnAnimatorBeginFrame(fml::TimePoint frame_target_time) override; // |Animator::Delegate| void OnAnimatorNotifyIdle(int64_t deadline) override; @@ -517,6 +521,9 @@ class Shell final : public PlatformView::Delegate, // |Rasterizer::Delegate| fml::Milliseconds GetFrameBudget() override; + // |Rasterizer::Delegate| + fml::TimePoint GetLatestFrameTargetTime() const override; + // |ServiceProtocol::Handler| fml::RefPtr GetServiceProtocolHandlerTaskRunner( std::string_view method) const override; diff --git a/shell/common/shell_test.cc b/shell/common/shell_test.cc index 5522feb591f79..378375c5eac1e 100644 --- a/shell/common/shell_test.cc +++ b/shell/common/shell_test.cc @@ -250,6 +250,10 @@ TaskRunners ShellTest::GetTaskRunnersForFixture() { }; } +fml::TimePoint ShellTest::GetLatestFrameTargetTime(Shell* shell) const { + return shell->GetLatestFrameTargetTime(); +} + std::unique_ptr ShellTest::CreateShell(Settings settings, bool simulate_vsync) { return CreateShell(std::move(settings), GetTaskRunnersForFixture(), diff --git a/shell/common/shell_test.h b/shell/common/shell_test.h index 7d35853cdbec6..79eaf2554991c 100644 --- a/shell/common/shell_test.h +++ b/shell/common/shell_test.h @@ -19,6 +19,7 @@ #include "flutter/testing/elf_loader.h" #include "flutter/testing/test_dart_native_resolver.h" #include "flutter/testing/thread_test.h" +#include "fml/time/time_point.h" namespace flutter { namespace testing { @@ -37,6 +38,8 @@ class ShellTest : public ThreadTest { void DestroyShell(std::unique_ptr shell, TaskRunners task_runners); TaskRunners GetTaskRunnersForFixture(); + fml::TimePoint GetLatestFrameTargetTime(Shell* shell) const; + void SendEnginePlatformMessage(Shell* shell, fml::RefPtr message);