fuchsia: Log vsync stats in inspect (#27433)

Author: arbreng

shell/platform/fuchsia/flutter/BUILD.gn

@@ -110,6 +110,7 @@ template("runner_sources") {
     ]
 
     public_deps = [
+                    "$fuchsia_sdk_root/pkg:inspect",
                     "$fuchsia_sdk_root/pkg:scenic_cpp",
                     "$fuchsia_sdk_root/pkg:sys_cpp",
                     "$fuchsia_sdk_root/pkg:sys_inspect_cpp",

shell/platform/fuchsia/flutter/default_session_connection.cc

@@ -4,9 +4,15 @@
 
 #include "default_session_connection.h"
 
+#include <lib/async/cpp/task.h>
+#include <lib/async/default.h>
+#include <lib/fit/function.h>
+
 #include "flutter/fml/make_copyable.h"
 #include "flutter/fml/trace_event.h"
 
+#include "fml/time/time_point.h"
+#include "runtime/dart/utils/root_inspect_node.h"
 #include "vsync_waiter.h"
 
 namespace flutter_runner {
@@ -175,6 +181,27 @@ DefaultSessionConnection::DefaultSessionConnection(
     uint64_t max_frames_in_flight,
     fml::TimeDelta vsync_offset)
     : session_wrapper_(session.Bind(), nullptr),
+      inspect_node_(
+          dart_utils::RootInspectNode::CreateRootChild("vsync_stats")),
+      secondary_vsyncs_completed_(
+          inspect_node_.CreateUint("SecondaryVsyncsCompleted", 0u)),
+      vsyncs_requested_(inspect_node_.CreateUint("VsyncsRequested", 0u)),
+      vsyncs_completed_(inspect_node_.CreateUint("VsyncsCompleted", 0u)),
+      presents_requested_(inspect_node_.CreateUint("PresentsRequested", 0u)),
+      presents_submitted_(inspect_node_.CreateUint("PresentsSubmitted", 0u)),
+      presents_completed_(inspect_node_.CreateUint("PresentsCompleted", 0u)),
+      last_secondary_vsync_completed_(
+          inspect_node_.CreateInt("LastSecondaryVsyncCompleteTime", 0)),
+      last_vsync_requested_(inspect_node_.CreateInt("LastVsyncRequestTime", 0)),
+      last_vsync_completed_(
+          inspect_node_.CreateInt("LastVsyncCompleteTime", 0)),
+      last_frame_requested_(
+          inspect_node_.CreateInt("LastPresentRequestTime", 0)),
+      last_frame_presented_(
+          inspect_node_.CreateInt("LastPresentSubmitTime", 0)),
+      last_frame_completed_(
+          inspect_node_.CreateInt("LastSubmitCompleteTime", 0)),
+      inspect_dispatcher_(async_get_default_dispatcher()),
       on_frame_presented_callback_(std::move(on_frame_presented_callback)),
       kMaxFramesInFlight(max_frames_in_flight),
       vsync_offset_(vsync_offset) {
@@ -207,6 +234,16 @@ DefaultSessionConnection::DefaultSessionConnection(
         last_presentation_time_ = fml::TimePoint::FromEpochDelta(
             fml::TimeDelta::FromNanoseconds(info.actual_presentation_time));
 
+        // Scenic retired a given number of frames, so mark them as completed.
+        // Inspect updates must run on the inspect dispatcher.
+        async::PostTask(
+            inspect_dispatcher_,
+            [this, num_presents_handled,
+             now = fml::TimePoint::Now().ToEpochDelta().ToNanoseconds()]() {
+              presents_completed_.Add(num_presents_handled);
+              last_frame_completed_.Set(now);
+            });
+
         if (fire_callback_request_pending_) {
           FireCallbackMaybe();
         }
@@ -251,7 +288,17 @@ void DefaultSessionConnection::Present() {
                    next_present_session_trace_id_);
   ++next_present_session_trace_id_;
 
-  present_requested_time_ = fml::TimePoint::Now();
+  auto now = fml::TimePoint::Now();
+  present_requested_time_ = now;
+
+  // Flutter is requesting a frame here, so mark it as such.
+  // Inspect updates must run on the inspect dispatcher.
+  async::PostTask(
+      inspect_dispatcher_,
+      [this, now = fml::TimePoint::Now().ToEpochDelta().ToNanoseconds()]() {
+        presents_requested_.Add(1);
+        last_frame_requested_.Set(now);
+      });
 
   // Throttle frame submission to Scenic if we already have the maximum amount
   // of frames in flight. This allows the paint tasks for this frame to execute
@@ -272,6 +319,15 @@ void DefaultSessionConnection::AwaitVsync(FireCallbackCallback callback) {
   TRACE_DURATION("flutter", "DefaultSessionConnection::AwaitVsync");
   fire_callback_ = callback;
 
+  // Flutter is requesting a vsync here, so mark it as such.
+  // Inspect updates must run on the inspect dispatcher.
+  async::PostTask(
+      inspect_dispatcher_,
+      [this, now = fml::TimePoint::Now().ToEpochDelta().ToNanoseconds()]() {
+        vsyncs_requested_.Add(1);
+        last_vsync_requested_.Set(now);
+      });
+
   FireCallbackMaybe();
 }
 
@@ -282,6 +338,15 @@ void DefaultSessionConnection::AwaitVsyncForSecondaryCallback(
                  "DefaultSessionConnection::AwaitVsyncForSecondaryCallback");
   fire_callback_ = callback;
 
+  // Flutter is requesting a secondary vsync here, so mark it as such.
+  // Inspect updates must run on the inspect dispatcher.
+  async::PostTask(
+      inspect_dispatcher_,
+      [this, now = fml::TimePoint::Now().ToEpochDelta().ToNanoseconds()]() {
+        secondary_vsyncs_completed_.Add(1);
+        last_secondary_vsync_completed_.Set(now);
+      });
+
   FlutterFrameTimes times = GetTargetTimesHelper(/*secondary_callback=*/true);
   fire_callback_(times.frame_start, times.frame_target);
 }
@@ -316,6 +381,15 @@ void DefaultSessionConnection::PresentSession() {
 
   last_latch_point_targeted_ = next_latch_point;
 
+  // Flutter is presenting a frame here, so mark it as such.
+  // Inspect updates must run on the inspect dispatcher.
+  async::PostTask(
+      inspect_dispatcher_,
+      [this, now = fml::TimePoint::Now().ToEpochDelta().ToNanoseconds()]() {
+        presents_submitted_.Add(1);
+        last_frame_presented_.Set(now);
+      });
+
   session_wrapper_.Present2(
       /*requested_presentation_time=*/next_latch_point.ToEpochDelta()
           .ToNanoseconds(),
@@ -357,6 +431,15 @@ void DefaultSessionConnection::FireCallbackMaybe() {
     last_targeted_vsync_ = times.frame_target;
     fire_callback_request_pending_ = false;
 
+    // Scenic completed a vsync here, so mark it as such.
+    // Inspect updates must run on the inspect dispatcher.
+    async::PostTask(
+        inspect_dispatcher_,
+        [this, now = fml::TimePoint::Now().ToEpochDelta().ToNanoseconds()]() {
+          vsyncs_completed_.Add(1);
+          last_vsync_completed_.Set(now);
+        });
+
     fire_callback_(times.frame_start, times.frame_target);
   } else {
     fire_callback_request_pending_ = true;

shell/platform/fuchsia/flutter/default_session_connection.h

@@ -7,7 +7,9 @@
 
 #include <fuchsia/scenic/scheduling/cpp/fidl.h>
 #include <fuchsia/ui/scenic/cpp/fidl.h>
+#include <lib/async/dispatcher.h>
 #include <lib/fidl/cpp/interface_handle.h>
+#include <lib/inspect/cpp/inspect.h>
 #include <lib/ui/scenic/cpp/session.h>
 
 #include "flutter/fml/closure.h"
@@ -102,6 +104,21 @@ class DefaultSessionConnection final {
 
   scenic::Session session_wrapper_;
 
+  inspect::Node inspect_node_;
+  inspect::UintProperty secondary_vsyncs_completed_;
+  inspect::UintProperty vsyncs_requested_;
+  inspect::UintProperty vsyncs_completed_;
+  inspect::UintProperty presents_requested_;
+  inspect::UintProperty presents_submitted_;
+  inspect::UintProperty presents_completed_;
+  inspect::IntProperty last_secondary_vsync_completed_;
+  inspect::IntProperty last_vsync_requested_;
+  inspect::IntProperty last_vsync_completed_;
+  inspect::IntProperty last_frame_requested_;
+  inspect::IntProperty last_frame_presented_;
+  inspect::IntProperty last_frame_completed_;
+  async_dispatcher_t* inspect_dispatcher_;
+
   on_frame_presented_event on_frame_presented_callback_;
 
   fml::TimePoint last_latch_point_targeted_ =