From bb4a69a8227742b68c1fb4e6c256752f1c53b579 Mon Sep 17 00:00:00 2001 From: David Worsham Date: Wed, 14 Jul 2021 21:26:19 -0700 Subject: [PATCH] fuchsia: Log vsync stats in inspect --- shell/platform/fuchsia/flutter/BUILD.gn | 1 + .../flutter/default_session_connection.cc | 85 ++++++++++++++++++- .../flutter/default_session_connection.h | 17 ++++ 3 files changed, 102 insertions(+), 1 deletion(-) diff --git a/shell/platform/fuchsia/flutter/BUILD.gn b/shell/platform/fuchsia/flutter/BUILD.gn index bed2393d1384e..218f751c7210f 100644 --- a/shell/platform/fuchsia/flutter/BUILD.gn +++ b/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", diff --git a/shell/platform/fuchsia/flutter/default_session_connection.cc b/shell/platform/fuchsia/flutter/default_session_connection.cc index 0c1d6c392d90b..0ebc9d30aed4c 100644 --- a/shell/platform/fuchsia/flutter/default_session_connection.cc +++ b/shell/platform/fuchsia/flutter/default_session_connection.cc @@ -4,9 +4,15 @@ #include "default_session_connection.h" +#include +#include +#include + #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; diff --git a/shell/platform/fuchsia/flutter/default_session_connection.h b/shell/platform/fuchsia/flutter/default_session_connection.h index 467f90f10acdf..7336362045ebc 100644 --- a/shell/platform/fuchsia/flutter/default_session_connection.h +++ b/shell/platform/fuchsia/flutter/default_session_connection.h @@ -7,7 +7,9 @@ #include #include +#include #include +#include #include #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_ =