[pipeline] Add trace event for lag between target and display times (#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.

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; }

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<const char*>& 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<const char*>& c_names,
+                        const std::vector<std::string>& 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<const char*>& c_names,
+                        const std::vector<std::string>& values) {}
+
 void TraceTimelineEvent(TraceArg category_group,
                         TraceArg name,
                         TraceIDArg identifier,

fml/trace_event.h

@@ -114,6 +114,14 @@ using TraceIDArg = int64_t;
 
 void TraceSetWhitelist(const std::vector<std::string>& whitelist);
 
+void TraceTimelineEvent(TraceArg category_group,
+                        TraceArg name,
+                        int64_t timestamp_micros,
+                        TraceIDArg id,
+                        Dart_Timeline_Event_Type type,
+                        const std::vector<const char*>& names,
+                        const std::vector<std::string>& values);
+
 void TraceTimelineEvent(TraceArg category_group,
                         TraceArg name,
                         TraceIDArg id,
@@ -209,10 +217,40 @@ void TraceEvent2(TraceArg category_group,
 
 void TraceEventEnd(TraceArg name);
 
+template <typename... Args>
 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,

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;
 

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());

shell/common/rasterizer.cc

@@ -8,6 +8,8 @@
 
 #include <utility>
 
+#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.

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());
+    }
   };
 
   //----------------------------------------------------------------------------

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<fml::TaskRunner> Shell::GetServiceProtocolHandlerTaskRunner(
     std::string_view method) const {

shell/common/shell.h

@@ -6,6 +6,7 @@
 #define SHELL_COMMON_SHELL_H_
 
 #include <functional>
+#include <mutex>
 #include <string_view>
 #include <unordered_map>
 
@@ -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<fml::TimePoint> latest_frame_target_time_;
   std::unique_ptr<PlatformView> platform_view_;  // on platform task runner
   std::unique_ptr<Engine> engine_;               // on UI task runner
   std::unique_ptr<Rasterizer> 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<fml::TaskRunner> GetServiceProtocolHandlerTaskRunner(
       std::string_view method) const override;

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<Shell> ShellTest::CreateShell(Settings settings,
                                               bool simulate_vsync) {
   return CreateShell(std::move(settings), GetTaskRunnersForFixture(),

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> shell, TaskRunners task_runners);
   TaskRunners GetTaskRunnersForFixture();
 
+  fml::TimePoint GetLatestFrameTargetTime(Shell* shell) const;
+
   void SendEnginePlatformMessage(Shell* shell,
                                  fml::RefPtr<PlatformMessage> message);