Report time for force installed extensions to become ready

Currently we are only reporting metrics when force installed extensions
either fail installation or ExtensionRegistry's OnExtensionLoaded (...)
event is received.
This CL reports the time elapsed for enterprise policy forced
extensions to become ready for use by reporting statistics when force
installed extensions either fail installation or ExtensionRegistry's
OnExtensionReady(...) event is received.
These statistics are being collected as part of the effort to improve
force installed extensions reliability.

Following histogram is added:
Extensions.ForceInstalledReadyTime

Bug: 1131418
Change-Id: Ief524819deb8cca81231765439700c265d9e7b96
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2424286Reviewed-by: Robert Kaplow <rkaplow@chromium.org>
Reviewed-by: Swapnil Gupta <swapnilgupta@google.com>
Reviewed-by: Oleg Davydov <burunduk@chromium.org>
Commit-Queue: Saurabh Nijhara <snijhara@google.com>
Cr-Commit-Position: refs/heads/master@{#811223}

chrome/browser/extensions/forced_extensions/force_installed_metrics.cc

@@ -285,6 +285,15 @@ void ForceInstalledMetrics::ReportDisableReason(
                            disable_reasons);
 }
 
+void ForceInstalledMetrics::ReportMetricsOnExtensionsReady() {
+  for (const auto& extension : tracker_->extensions()) {
+    if (extension.second.status != ExtensionStatus::READY)
+      return;
+  }
+  base::UmaHistogramLongTimes("Extensions.ForceInstalledReadyTime",
+                              base::Time::Now() - start_time_);
+}
+
 void ForceInstalledMetrics::ReportMetrics() {
   base::UmaHistogramCounts100("Extensions.ForceInstalledTotalCandidateCount",
                               tracker_->extensions().size());
@@ -305,7 +314,7 @@ void ForceInstalledMetrics::ReportMetrics() {
                                 base::Time::Now() - start_time_);
     // TODO(burunduk): Remove VLOGs after resolving crbug/917700 and
     // crbug/904600.
-    VLOG(2) << "All forced extensions seems to be installed";
+    VLOG(2) << "All forced extensions seem to be installed";
     return;
   }
   size_t enabled_missing_count = missing_forced_extensions.size();
@@ -385,15 +394,24 @@ void ForceInstalledMetrics::ReportMetrics() {
 }
 
 void ForceInstalledMetrics::OnForceInstalledExtensionsLoaded() {
-  if (reported_)
+  if (load_reported_)
     return;
   // Report only if there was non-empty list of force-installed extensions.
   if (!tracker_->extensions().empty())
     ReportMetrics();
-  reported_ = true;
+  load_reported_ = true;
   timer_->Stop();
 }
 
+void ForceInstalledMetrics::OnForceInstalledExtensionsReady() {
+  if (ready_reported_)
+    return;
+  // Report only if there was non-empty list of force-installed extensions.
+  if (!tracker_->extensions().empty())
+    ReportMetricsOnExtensionsReady();
+  ready_reported_ = true;
+}
+
 void ForceInstalledMetrics::OnExtensionDownloadCacheStatusRetrieved(
     const ExtensionId& id,
     ExtensionDownloaderDelegate::CacheStatus cache_status) {

chrome/browser/extensions/forced_extensions/force_installed_metrics.h

@@ -63,6 +63,10 @@ class ForceInstalledMetrics : public ForceInstalledTracker::Observer {
   // observers.
   void OnForceInstalledExtensionsLoaded() override;
 
+  // Calls ReportMetricsOnExtensionsReady method if there is a non-empty list of
+  // force-installed extensions.
+  void OnForceInstalledExtensionsReady() override;
+
   // Reports cache status for the force installed extensions.
   void OnExtensionDownloadCacheStatusRetrieved(
       const ExtensionId& id,
@@ -82,6 +86,10 @@ class ForceInstalledMetrics : public ForceInstalledTracker::Observer {
   // why they were not installed.
   void ReportMetrics();
 
+  // Reports metrics for sessions when all force installed extensions are ready
+  // for use.
+  void ReportMetricsOnExtensionsReady();
+
   ExtensionRegistry* const registry_;
   Profile* const profile_;
   ForceInstalledTracker* const tracker_;
@@ -89,8 +97,12 @@ class ForceInstalledMetrics : public ForceInstalledTracker::Observer {
   // Moment when the class was initialized.
   base::Time start_time_;
 
-  // Tracks whether stats were already reported for the session.
-  bool reported_ = false;
+  // Tracks whether extensions load stats were already for the session.
+  bool load_reported_ = false;
+
+  // Tracks whether extensions ready stats were already reported for the
+  // session.
+  bool ready_reported_ = false;
 
   ScopedObserver<ForceInstalledTracker, ForceInstalledTracker::Observer>
       tracker_observer_{this};

chrome/browser/extensions/forced_extensions/force_installed_metrics_unittest.cc

@@ -49,6 +49,7 @@ const int kFetchTries = 5;
 const int kResponseCode = 401;
 
 constexpr char kLoadTimeStats[] = "Extensions.ForceInstalledLoadTime";
+constexpr char kReadyTimeStats[] = "Extensions.ForceInstalledReadyTime";
 constexpr char kTimedOutStats[] = "Extensions.ForceInstalledTimedOutCount";
 constexpr char kTimedOutNotInstalledStats[] =
     "Extensions.ForceInstalledTimedOutAndNotInstalledCount";
@@ -181,6 +182,7 @@ TEST_F(ForceInstalledMetricsTest, EmptyForcelist) {
   EXPECT_FALSE(fake_timer_->IsRunning());
   // Don't report metrics when the Forcelist is empty.
   histogram_tester_.ExpectTotalCount(kLoadTimeStats, 0);
+  histogram_tester_.ExpectTotalCount(kReadyTimeStats, 0);
   histogram_tester_.ExpectTotalCount(kTimedOutStats, 0);
   histogram_tester_.ExpectTotalCount(kTimedOutNotInstalledStats, 0);
   histogram_tester_.ExpectTotalCount(kFailureReasonsCWS, 0);
@@ -201,6 +203,7 @@ TEST_F(ForceInstalledMetricsTest, ExtensionsInstalled) {
   force_installed_tracker()->OnExtensionLoaded(profile(), ext2.get());
 
   histogram_tester_.ExpectTotalCount(kLoadTimeStats, 1);
+  histogram_tester_.ExpectTotalCount(kReadyTimeStats, 0);
   histogram_tester_.ExpectTotalCount(kTimedOutStats, 0);
   histogram_tester_.ExpectTotalCount(kTimedOutNotInstalledStats, 0);
   histogram_tester_.ExpectTotalCount(kFailureReasonsCWS, 0);
@@ -573,7 +576,8 @@ TEST_F(ForceInstalledMetricsTest,
 }
 
 // Regression test to check if the metrics are collected properly for the
-// extensions which are in state READY.
+// extensions which are in state READY. Also verifies that the failure reported
+// after READY state is not reflected in the statistics.
 TEST_F(ForceInstalledMetricsTest, ExtensionsReady) {
   SetupForceList();
   auto ext1 = ExtensionBuilder(kExtensionName1).SetID(kExtensionId1).Build();
@@ -588,8 +592,28 @@ TEST_F(ForceInstalledMetricsTest, ExtensionsReady) {
   // loaded or failed.
   EXPECT_FALSE(fake_timer_->IsRunning());
   histogram_tester_.ExpectTotalCount(kLoadTimeStats, 1);
+  histogram_tester_.ExpectTotalCount(kReadyTimeStats, 1);
   histogram_tester_.ExpectTotalCount(kTimedOutStats, 0);
   histogram_tester_.ExpectTotalCount(kTimedOutNotInstalledStats, 0);
+  histogram_tester_.ExpectTotalCount(kFailureReasonsCWS, 0);
+}
+
+// Regression test to check if no metrics are reported for READY state when some
+// extensions are failed.
+TEST_F(ForceInstalledMetricsTest, AllExtensionsNotReady) {
+  SetupForceList();
+  auto ext1 = ExtensionBuilder(kExtensionName1).SetID(kExtensionId1).Build();
+  force_installed_tracker()->OnExtensionLoaded(profile(), ext1.get());
+  force_installed_tracker()->OnExtensionReady(profile(), ext1.get());
+  install_stage_tracker()->ReportFailure(
+      kExtensionId2, InstallStageTracker::FailureReason::INVALID_ID);
+  // ForceInstalledMetrics shuts down timer because all extension are either
+  // loaded or failed.
+  EXPECT_FALSE(fake_timer_->IsRunning());
+  histogram_tester_.ExpectTotalCount(kLoadTimeStats, 0);
+  histogram_tester_.ExpectTotalCount(kReadyTimeStats, 0);
+  histogram_tester_.ExpectBucketCount(
+      kFailureReasonsCWS, InstallStageTracker::FailureReason::INVALID_ID, 1);
 }
 
 // Verifies that the installation stage is not overwritten by a previous stage.
@@ -1068,6 +1092,7 @@ TEST_F(ForceInstalledMetricsTest, NoExtensionsConfigured) {
   EXPECT_TRUE(fake_timer_->IsRunning());
   fake_timer_->Fire();
   histogram_tester_.ExpectTotalCount(kLoadTimeStats, 0);
+  histogram_tester_.ExpectTotalCount(kReadyTimeStats, 0);
   histogram_tester_.ExpectTotalCount(kTimedOutStats, 0);
   histogram_tester_.ExpectTotalCount(kTimedOutNotInstalledStats, 0);
   histogram_tester_.ExpectTotalCount(kFailureReasonsCWS, 0);

chrome/browser/extensions/forced_extensions/force_installed_tracker_unittest.cc

@@ -161,4 +161,18 @@ TEST_F(ForceInstalledTrackerTest, ExtensionsInstallationCancelled) {
   EXPECT_FALSE(ready_called_);
 }
 
+// This test verifies that READY state observer is called when each force
+// installed extension is either ready for use or failed.
+TEST_F(ForceInstalledTrackerTest, AllExtensionsReady) {
+  SetupForceList();
+  auto ext1 = ExtensionBuilder(kExtensionName1).SetID(kExtensionId1).Build();
+  force_installed_tracker()->OnExtensionLoaded(profile(), ext1.get());
+  force_installed_tracker()->OnExtensionReady(profile(), ext1.get());
+  force_installed_tracker()->OnExtensionInstallationFailed(
+      kExtensionId2, InstallStageTracker::FailureReason::INVALID_ID);
+  EXPECT_TRUE(loaded_called_);
+  EXPECT_TRUE(ready_called_);
+  EXPECT_TRUE(force_installed_tracker()->IsDoneLoading());
+}
+
 }  // namespace extensions

tools/metrics/histograms/histograms_xml/extensions/histograms.xml

@@ -1573,6 +1573,18 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
   </summary>
 </histogram>
 
+<histogram name="Extensions.ForceInstalledReadyTime" units="ms"
+    expires_after="2021-01-24">
+  <owner>snijhara@google.com</owner>
+  <owner>burunduk@chromium.org</owner>
+  <owner>swapnilgupta@google.com</owner>
+  <owner>managed-devices@google.com</owner>
+  <summary>
+    The amount of time elapsed for enterprise policy forced extensions to become
+    ready for use.
+  </summary>
+</histogram>
+
 <histogram
     name="Extensions.ForceInstalledSessionsWithNonMisconfigurationFailureOccured"
     enum="Boolean" expires_after="2021-01-24">