arc-tracing: UMA metric for time from launch to first frame rendered

Implements an UMA metric to trace time spent from app launch to
first frame, detected by first commit to exo surface.

Bug= b:171066921
Test= Launch PlayStore and other apps from launcher and check
chrome://histograms. Also launch apps from PlayStore and make sure
nothing breaks and the values make sense.

Change-Id: I924f70c10f95bd916dd39fcc7a78f442c4900700
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2494061
Auto-Submit: Mustafa Camurcu <camurcu@chromium.org>
Commit-Queue: Mustafa Camurcu <camurcu@chromium.org>
Reviewed-by: Yury Khmel <khmel@chromium.org>
Cr-Commit-Position: refs/heads/master@{#828551}

chrome/browser/chromeos/arc/tracing/arc_app_performance_tracing.cc

@@ -12,12 +12,16 @@
 #include "chrome/browser/chromeos/arc/tracing/arc_app_performance_tracing_custom_session.h"
 #include "chrome/browser/chromeos/arc/tracing/arc_app_performance_tracing_session.h"
 #include "chrome/browser/chromeos/arc/tracing/arc_app_performance_tracing_uma_session.h"
+#include "chrome/browser/ui/app_list/arc/arc_app_list_prefs.h"
 #include "chrome/browser/ui/app_list/arc/arc_app_list_prefs_factory.h"
+#include "chrome/browser/ui/app_list/arc/arc_app_utils.h"
 #include "components/arc/arc_browser_context_keyed_service_factory_base.h"
 #include "components/arc/arc_features.h"
 #include "components/arc/arc_service_manager.h"
 #include "components/arc/arc_util.h"
 #include "components/arc/session/arc_bridge_service.h"
+#include "components/exo/shell_surface_util.h"
+#include "components/exo/surface.h"
 #include "components/exo/wm_helper.h"
 #include "ui/aura/window.h"
 
@@ -223,6 +227,28 @@ void ArcAppPerformanceTracing::StartJankinessTracing() {
                      base::Unretained(this), false /* stopped_early */));
 }
 
+void ArcAppPerformanceTracing::HandleActiveAppRendered(base::Time timestamp) {
+  const int32_t task_id = arc::GetWindowTaskId(arc_active_window_);
+  DCHECK_GT(task_id, 0);
+
+  const std::string& app_id = task_id_to_app_id_[task_id].first;
+  const base::Time launch_request_time =
+      ArcAppListPrefs::Get(context_)->PollLaunchRequestTime(app_id);
+  if (!launch_request_time.is_null()) {
+    base::UmaHistogramTimes(
+        "Arc.Runtime.Performance.Generic.FirstFrameRendered",
+        timestamp - launch_request_time);
+  }
+}
+
+void ArcAppPerformanceTracing::OnCommit(exo::Surface* surface) {
+  HandleActiveAppRendered(base::Time::Now());
+  // Only need first frame. We don't need to observe anymore.
+  surface->RemoveSurfaceObserver(this);
+}
+
+void ArcAppPerformanceTracing::OnSurfaceDestroying(exo::Surface* surface) {}
+
 void ArcAppPerformanceTracing::CancelJankinessTracing() {
   jankiness_timer_.Stop();
 }
@@ -371,15 +397,23 @@ void ArcAppPerformanceTracing::MaybeStopTracing() {
 void ArcAppPerformanceTracing::AttachActiveWindow(aura::Window* window) {
   DCHECK(window);
   DCHECK(!arc_active_window_);
-
   arc_active_window_ = window;
   arc_active_window_->AddObserver(this);
+
+  exo::Surface* const surface = exo::GetShellMainSurface(window);
+  DCHECK(surface);
+  surface->AddSurfaceObserver(this);
 }
 
 void ArcAppPerformanceTracing::DetachActiveWindow() {
   if (!arc_active_window_)
     return;
 
+  exo::Surface* const surface = exo::GetShellMainSurface(arc_active_window_);
+  // Surface might be destroyed.
+  if (surface)
+    surface->RemoveSurfaceObserver(this);
+
   arc_active_window_->RemoveObserver(this);
   arc_active_window_ = nullptr;
 }

chrome/browser/chromeos/arc/tracing/arc_app_performance_tracing.h

@@ -14,8 +14,10 @@
 
 #include "base/callback.h"
 #include "base/macros.h"
+#include "base/time/time.h"
 #include "chrome/browser/ui/app_list/arc/arc_app_list_prefs.h"
 #include "components/arc/mojom/metrics.mojom.h"
+#include "components/exo/surface_observer.h"
 #include "components/keyed_service/core/keyed_service.h"
 #include "ui/aura/window_observer.h"
 #include "ui/wm/public/activation_change_observer.h"
@@ -38,7 +40,8 @@ class ArcBridgeService;
 class ArcAppPerformanceTracing : public KeyedService,
                                  public wm::ActivationChangeObserver,
                                  public aura::WindowObserver,
-                                 public ArcAppListPrefs::Observer {
+                                 public ArcAppListPrefs::Observer,
+                                 public exo::SurfaceObserver {
  public:
   using ResultCallback = base::OnceCallback<void(bool success,
                                                  double fps,
@@ -86,6 +89,12 @@ class ArcAppPerformanceTracing : public KeyedService,
                      const std::string& intent) override;
   void OnTaskDestroyed(int32_t task_id) override;
 
+  // exo::SurfaceObserver:
+  void OnCommit(exo::Surface* surface) override;
+  void OnSurfaceDestroying(exo::Surface* surface) override;
+
+  void HandleActiveAppRendered(base::Time timestamp);
+
   // Returns true in case |category| was already reported in the current user's
   // session.
   bool WasReported(const std::string& category) const;
@@ -148,6 +157,9 @@ class ArcAppPerformanceTracing : public KeyedService,
   // Maps active tasks to app id and package name.
   std::map<int, std::pair<std::string, std::string>> task_id_to_app_id_;
 
+  // Set of tasks that have already rendered first frame.
+  std::set<int> rendered_tasks_;
+
   // Maps tasks to most recent GFX jankiness results. Used for delta
   // calculation.
   std::map<std::string, mojom::GfxMetrics> package_name_to_gfx_metrics_;

chrome/browser/chromeos/arc/tracing/arc_app_performance_tracing_unittest.cc

@@ -13,6 +13,8 @@
 #include "chrome/browser/ui/app_list/arc/arc_app_test.h"
 #include "chrome/test/base/browser_with_test_window_test.h"
 #include "chrome/test/base/testing_profile.h"
+#include "components/exo/shell_surface_util.h"
+#include "components/exo/surface.h"
 #include "testing/gtest/include/gtest/gtest.h"
 #include "ui/views/widget/widget.h"
 
@@ -30,6 +32,8 @@ constexpr char kNonFocusAppActivity[] = "nonfocus.app.package.Activity";
 constexpr base::TimeDelta kTestPeriod =
     base::TimeDelta::FromSeconds(1) / (60 / 20);
 
+constexpr int kMillisecondsToFirstFrame = 500;
+
 // Creates name of histogram with required statistics.
 std::string GetFocusStatisticName(const std::string& name) {
   return base::StringPrintf("Arc.Runtime.Performance.%s.%s", name.c_str(),
@@ -204,4 +208,50 @@ TEST_F(ArcAppPerformanceTracingTest, StatisticsReported) {
   arc_widget->Close();
 }
 
+TEST_F(ArcAppPerformanceTracingTest, TimeToFirstFrameRendered) {
+  const std::string app_id =
+      ArcAppListPrefs::GetAppId(kFocusAppPackage, kFocusAppActivity);
+  views::Widget* const arc_widget =
+      ArcAppPerformanceTracingTestHelper::CreateArcWindow("org.chromium.arc.1");
+  DCHECK(arc_widget && arc_widget->GetNativeWindow());
+
+  tracing_helper().GetTracing()->OnWindowActivated(
+      wm::ActivationChangeObserver::ActivationReason::ACTIVATION_CLIENT,
+      arc_widget->GetNativeWindow(), arc_widget->GetNativeWindow());
+  tracing_helper().GetTracing()->OnTaskCreated(
+      1 /* task_Id */, kFocusAppPackage, kFocusAppActivity,
+      std::string() /* intent */);
+
+  // No report before launch
+  base::Time timestamp = base::Time::Now();
+  tracing_helper().GetTracing()->HandleActiveAppRendered(timestamp);
+  base::HistogramBase* histogram = base::StatisticsRecorder::FindHistogram(
+      "Arc.Runtime.Performance.Generic.FirstFrameRendered");
+  DCHECK(!histogram);
+
+  // Succesful report after launch
+  ArcAppListPrefs::Get(profile())->SetLaunchRequestTimeForTesting(app_id,
+                                                                  timestamp);
+  timestamp += base::TimeDelta::FromMilliseconds(kMillisecondsToFirstFrame);
+  tracing_helper().GetTracing()->HandleActiveAppRendered(timestamp);
+  histogram = base::StatisticsRecorder::FindHistogram(
+      "Arc.Runtime.Performance.Generic.FirstFrameRendered");
+  DCHECK(histogram);
+
+  std::unique_ptr<base::HistogramSamples> samples = histogram->SnapshotDelta();
+  DCHECK(samples.get());
+  EXPECT_EQ(1, samples->TotalCount());
+  EXPECT_EQ(kMillisecondsToFirstFrame, samples->sum());
+
+  // No double report
+  timestamp += base::TimeDelta::FromMilliseconds(kMillisecondsToFirstFrame);
+  tracing_helper().GetTracing()->HandleActiveAppRendered(timestamp);
+
+  samples = histogram->SnapshotDelta();
+  DCHECK(samples.get());
+  EXPECT_EQ(0, samples->TotalCount());
+
+  arc_widget->Close();
+}
+
 }  // namespace arc

chrome/browser/ui/app_list/arc/arc_app_list_prefs.cc

@@ -828,12 +828,31 @@ bool ArcAppListPrefs::IsControlledByPolicy(
   return packages_by_policy_.count(package_name);
 }
 
+base::Time ArcAppListPrefs::PollLaunchRequestTime(const std::string& app_id) {
+  if (!launch_request_times_.count(app_id))
+    return base::Time();
+
+  const base::Time last_launch_time = launch_request_times_[app_id];
+  // This value should only be used once per launch.
+  launch_request_times_.erase(app_id);
+  return last_launch_time;
+}
+
+void ArcAppListPrefs::SetLaunchRequestTimeForTesting(const std::string& app_id,
+                                                     base::Time timestamp) {
+  launch_request_times_[app_id] = timestamp;
+}
 void ArcAppListPrefs::SetLastLaunchTime(const std::string& app_id) {
   if (!IsRegistered(app_id)) {
     NOTREACHED();
     return;
   }
 
+  launch_request_times_[app_id] = base::Time::Now();
+  SetLastLaunchTimeInternal(app_id);
+}
+
+void ArcAppListPrefs::SetLastLaunchTimeInternal(const std::string& app_id) {
   // Usage time on hidden should not be tracked.
   if (!arc::ShouldShowInLauncher(app_id))
     return;
@@ -1089,7 +1108,7 @@ void ArcAppListPrefs::HandleTaskCreated(const base::Optional<std::string>& name,
   DCHECK(IsArcAndroidEnabledForProfile(profile_));
   const std::string app_id = GetAppId(package_name, activity);
   if (IsRegistered(app_id)) {
-    SetLastLaunchTime(app_id);
+    SetLastLaunchTimeInternal(app_id);
   } else {
     // Create runtime app entry that is valid for the current user session. This
     // entry is not shown in App Launcher and only required for shelf

chrome/browser/ui/app_list/arc/arc_app_list_prefs.h

@@ -299,8 +299,14 @@ class ArcAppListPrefs : public KeyedService,
       const std::string& app_id,
       const ArcAppIconDescriptor& descriptor) const;
 
+  // Returns and resets launch request time for the given app id.
+  // Returns base::Time() value if launch request time wasn't recorded.
+  base::Time PollLaunchRequestTime(const std::string& app_id);
+
   // Sets last launched time for the requested app.
   void SetLastLaunchTime(const std::string& app_id);
+  void SetLaunchRequestTimeForTesting(const std::string& app_id,
+                                      base::Time timestamp);
 
   // Calls RequestIcon if no request is recorded.
   void MaybeRequestIcon(const std::string& app_id,
@@ -438,6 +444,9 @@ class ArcAppListPrefs : public KeyedService,
   void SetDefaultAppsFilterLevel();
   void RegisterDefaultApps();
 
+  // Sets last launched time for the requested app.
+  void SetLastLaunchTimeInternal(const std::string& app_id);
+
   // Returns list of packages from prefs. If |installed| is set to true then
   // returns currently installed packages. If not, returns list of packages that
   // where uninstalled. Note, we store uninstall packages only for packages of
@@ -607,6 +616,11 @@ class ArcAppListPrefs : public KeyedService,
   // TODO (b/70566216): Remove this once fixed.
   base::OnceClosure app_list_refreshed_callback_;
 
+  // Records launch request time per app id.
+  // Stored runtime and for the current active session only.
+  // Not to be confused with `last_launch_time_`.
+  std::map<const std::string, base::Time> launch_request_times_;
+
   base::WeakPtrFactory<ArcAppListPrefs> weak_ptr_factory_{this};
 };