From ce0ec9042ff8a2d81fead6fe9a1ce111f91c3848 Mon Sep 17 00:00:00 2001 From: Kaushik Iska Date: Thu, 2 Apr 2020 17:15:45 -0700 Subject: [PATCH] [pipeline] Add trace event for lag between target and display times (flutter/engine#17384) 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. --- engine/src/flutter/fml/time/time_delta.h | 4 ++ engine/src/flutter/fml/trace_event.cc | 55 +++++++++---------- engine/src/flutter/fml/trace_event.h | 40 +++++++++++++- engine/src/flutter/shell/common/animator.h | 2 +- .../shell/common/animator_unittests.cc | 8 ++- engine/src/flutter/shell/common/rasterizer.cc | 32 ++++++++++- engine/src/flutter/shell/common/rasterizer.h | 11 ++++ engine/src/flutter/shell/common/shell.cc | 16 +++++- engine/src/flutter/shell/common/shell.h | 9 ++- engine/src/flutter/shell/common/shell_test.cc | 4 ++ engine/src/flutter/shell/common/shell_test.h | 3 + 11 files changed, 147 insertions(+), 37 deletions(-) diff --git a/engine/src/flutter/fml/time/time_delta.h b/engine/src/flutter/fml/time/time_delta.h index 98a11b41008..e54a1f8bf9b 100644 --- a/engine/src/flutter/fml/time/time_delta.h +++ b/engine/src/flutter/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/engine/src/flutter/fml/trace_event.cc b/engine/src/flutter/fml/trace_event.cc index 7e11b2c6f8e..d055582d3a0 100644 --- a/engine/src/flutter/fml/trace_event.cc +++ b/engine/src/flutter/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/engine/src/flutter/fml/trace_event.h b/engine/src/flutter/fml/trace_event.h index a90aed2ff64..98d328e1348 100644 --- a/engine/src/flutter/fml/trace_event.h +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/animator.h b/engine/src/flutter/shell/common/animator.h index ba5e1f4df40..f96acb7e9a3 100644 --- a/engine/src/flutter/shell/common/animator.h +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/animator_unittests.cc b/engine/src/flutter/shell/common/animator_unittests.cc index 3907cee3b89..ed54ea5272b 100644 --- a/engine/src/flutter/shell/common/animator_unittests.cc +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/rasterizer.cc b/engine/src/flutter/shell/common/rasterizer.cc index 4d7d5ea669b..0561b0ce4e4 100644 --- a/engine/src/flutter/shell/common/rasterizer.cc +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/rasterizer.h b/engine/src/flutter/shell/common/rasterizer.h index f6bdd297ed8..d4d57c5efe1 100644 --- a/engine/src/flutter/shell/common/rasterizer.h +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/shell.cc b/engine/src/flutter/shell/common/shell.cc index c09da8e4287..71ab4a95094 100644 --- a/engine/src/flutter/shell/common/shell.cc +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/shell.h b/engine/src/flutter/shell/common/shell.h index d6345f115bd..f8cbc85cd6c 100644 --- a/engine/src/flutter/shell/common/shell.h +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/shell_test.cc b/engine/src/flutter/shell/common/shell_test.cc index 5522feb591f..378375c5eac 100644 --- a/engine/src/flutter/shell/common/shell_test.cc +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/shell_test.h b/engine/src/flutter/shell/common/shell_test.h index 7d35853cdbe..79eaf255499 100644 --- a/engine/src/flutter/shell/common/shell_test.h +++ b/engine/src/flutter/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);