From c70c0e88621fb52803caeea6ad11b7a67e820bcf Mon Sep 17 00:00:00 2001
From: Ariana Mott <amott@google.com>
Date: Wed, 17 Apr 2019 01:55:35 +0000
Subject: [PATCH] [scenic] Add debug-report info for scheduled frames

Adds info capturing the last time each session applied an update to the
scene graph, and the timing of the most recently applied scenic frame.

Tested: ran fx debug-report on astro
Change-Id: Iea0ce669395384faa1b32553390ceadf67652b19
---
 .../ui/gfx/engine/default_frame_scheduler.cc   | 18 +++++++++++++++---
 .../ui/gfx/engine/default_frame_scheduler.h    |  2 ++
 garnet/lib/ui/gfx/engine/session.cc            | 11 ++++++++---
 garnet/lib/ui/gfx/engine/session.h             |  3 ++-
 4 files changed, 27 insertions(+), 7 deletions(-)

diff --git a/garnet/lib/ui/gfx/engine/default_frame_scheduler.cc b/garnet/lib/ui/gfx/engine/default_frame_scheduler.cc
index 9bed5266ea2..b7d25f43805 100644
--- a/garnet/lib/ui/gfx/engine/default_frame_scheduler.cc
+++ b/garnet/lib/ui/gfx/engine/default_frame_scheduler.cc
@@ -26,7 +26,11 @@ DefaultFrameScheduler::DefaultFrameScheduler(const Display* display,
   outstanding_frames_.reserve(kMaxOutstandingFrames);
 
   inspect_frame_number_ =
-      inspect_object_.CreateUIntMetric("frame_number", 0);
+      inspect_object_.CreateUIntMetric("most_recent_frame_number", frame_number_);
+  inspect_last_successful_update_start_time_ = inspect_object_.CreateUIntMetric(
+        "inspect_last_successful_update_start_time_", 0);
+  inspect_last_successful_render_start_time_ = inspect_object_.CreateUIntMetric(
+        "inspect_last_successful_render_start_time_", 0);
 }
 
 DefaultFrameScheduler::~DefaultFrameScheduler() {}
@@ -151,9 +155,14 @@ void DefaultFrameScheduler::MaybeRenderFrame(async_dispatcher_t*,
   FXL_DCHECK(delegate_.session_updater);
 
   // Apply all updates
+  const zx_time_t update_start_time = async_now(dispatcher_);
   bool any_updates_were_applied =
       ApplyScheduledSessionUpdates(presentation_time);
 
+  if (any_updates_were_applied) {
+    inspect_last_successful_update_start_time_.Set(update_start_time);
+  }
+
   if (!any_updates_were_applied && !render_pending_ && !render_continuously_) {
     // If necessary, schedule another frame.
     if (!updatable_sessions_.empty()) {
@@ -189,8 +198,7 @@ void DefaultFrameScheduler::MaybeRenderFrame(async_dispatcher_t*,
 
   auto frame_timings =
       fxl::MakeRefCounted<FrameTimings>(this, frame_number_, presentation_time);
-
-  ++frame_number_;
+  inspect_frame_number_.Set(frame_number_);
 
   // Render the frame.
   currently_rendering_ =
@@ -198,6 +206,8 @@ void DefaultFrameScheduler::MaybeRenderFrame(async_dispatcher_t*,
   if (currently_rendering_) {
     outstanding_frames_.push_back(frame_timings);
     render_pending_ = false;
+
+    inspect_last_successful_render_start_time_.Set(presentation_time);
   } else {
     // TODO(SCN-1344): Handle failed rendering somehow.
     FXL_LOG(WARNING)
@@ -206,6 +216,8 @@ void DefaultFrameScheduler::MaybeRenderFrame(async_dispatcher_t*,
         << "and no callbacks may be invoked.";
   }
 
+  ++frame_number_;
+
   // If necessary, schedule another frame.
   if (!updatable_sessions_.empty()) {
     RequestFrame();
diff --git a/garnet/lib/ui/gfx/engine/default_frame_scheduler.h b/garnet/lib/ui/gfx/engine/default_frame_scheduler.h
index d3ad23251ca..60a086745d9 100644
--- a/garnet/lib/ui/gfx/engine/default_frame_scheduler.h
+++ b/garnet/lib/ui/gfx/engine/default_frame_scheduler.h
@@ -116,6 +116,8 @@ class DefaultFrameScheduler : public FrameScheduler {
 
   inspect::Object inspect_object_;
   inspect::UIntMetric inspect_frame_number_;
+  inspect::UIntMetric inspect_last_successful_update_start_time_;
+  inspect::UIntMetric inspect_last_successful_render_start_time_;
 
   fxl::WeakPtrFactory<DefaultFrameScheduler> weak_factory_;  // must be last
 
diff --git a/garnet/lib/ui/gfx/engine/session.cc b/garnet/lib/ui/gfx/engine/session.cc
index ff2304c86a8..6566b41b182 100644
--- a/garnet/lib/ui/gfx/engine/session.cc
+++ b/garnet/lib/ui/gfx/engine/session.cc
@@ -75,8 +75,11 @@ Session::Session(SessionId id, SessionContext session_context,
 
   inspect_resource_count_ =
       inspect_object_.CreateUIntMetric("resource_count", 0);
-  inspect_last_applied_update_presentation_time_ =
-      inspect_object_.CreateUIntMetric("last_applied_update_presentation_time",
+  inspect_last_applied_target_presentation_time_ =
+      inspect_object_.CreateUIntMetric("last_applied_target_presentation_time",
+                                       0);
+  inspect_last_applied_requested_presentation_time_ =
+      inspect_object_.CreateUIntMetric("last_applied_request_presentation_time",
                                        0);
   inspect_last_requested_presentation_time_ =
       inspect_object_.CreateUIntMetric("last_requested_presentation_time", 0);
@@ -231,8 +234,10 @@ Session::ApplyUpdateResult Session::ApplyScheduledUpdates(
 
     // TODO(SCN-1202): gather statistics about how close the actual
     // presentation_time was to the requested time.
-    inspect_last_applied_update_presentation_time_.Set(
+    inspect_last_applied_requested_presentation_time_.Set(
         last_applied_update_presentation_time_);
+    inspect_last_applied_target_presentation_time_.Set(
+        target_presentation_time);
     inspect_resource_count_.Set(resource_count_);
   }
 
diff --git a/garnet/lib/ui/gfx/engine/session.h b/garnet/lib/ui/gfx/engine/session.h
index 04c24038cca..7146588f524 100644
--- a/garnet/lib/ui/gfx/engine/session.h
+++ b/garnet/lib/ui/gfx/engine/session.h
@@ -197,7 +197,8 @@ class Session {
 
   inspect::Object inspect_object_;
   inspect::UIntMetric inspect_resource_count_;
-  inspect::UIntMetric inspect_last_applied_update_presentation_time_;
+  inspect::UIntMetric inspect_last_applied_target_presentation_time_;
+  inspect::UIntMetric inspect_last_applied_requested_presentation_time_;
   inspect::UIntMetric inspect_last_requested_presentation_time_;
 
   fxl::WeakPtrFactory<Session> weak_factory_;  // must be last
-- 
GitLab