From dcb9d78458b267432e9feffec1ae3b5cd126bffa Mon Sep 17 00:00:00 2001 From: Kaushik Iska Date: Fri, 27 Mar 2020 17:35:07 -0700 Subject: [PATCH] [pipeline] Add trace event for lag between target and display times This change also adds TimeRecorder which records time at the start of each frame to capture the latest vsync target display time and wires it in to the rasterizer to add trace events when there is a lag. --- fml/time/time_delta.h | 4 +++ fml/trace_event.cc | 55 ++++++++++++++---------------- fml/trace_event.h | 40 +++++++++++++++++++++- shell/common/animator.h | 2 +- shell/common/animator_unittests.cc | 8 +++-- shell/common/rasterizer.cc | 32 ++++++++++++++++- shell/common/rasterizer.h | 11 ++++++ shell/common/shell.cc | 16 +++++++-- shell/common/shell.h | 9 ++++- shell/common/shell_test.cc | 4 +++ shell/common/shell_test.h | 3 ++ 11 files changed, 147 insertions(+), 37 deletions(-) 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);