Report extension installation times using UMA statistics

We want to improve the installation time for force installed
extensions. For this, we need to first gather the statistics regarding
which installation stages are time consuming.

This CL adds the UMA statistics for the following installation stages:
1) Unpacking - Time taken to complete the unpacking of the extension
archive.
2) Checking - Time taken to perform the final checks to confirm that the
extension can be installed.
3) Finalizing - Time taken to install the extension.

Following histograms are added:
Extensions.ForceInstalledTime.UnpackingStartTo.CheckingStart
Extensions.ForceInstalledTime.CheckingStartTo.FinalizingStart
Extensions.ForceInstalledTime.FinalizingStartTo.CRXInstallComplete

Bug: 1102369
Change-Id: I46ed872a2954edba51ebdaeab8ab0ca9e1f4703b
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2351996Reviewed-by: Devlin <rdevlin.cronin@chromium.org>
Reviewed-by: Oleg Davydov <burunduk@chromium.org>
Reviewed-by: Swapnil Gupta <swapnilgupta@google.com>
Reviewed-by: Steven Holte <holte@chromium.org>
Commit-Queue: Saurabh Nijhara <snijhara@google.com>
Cr-Commit-Position: refs/heads/master@{#799034}

chrome/browser/extensions/crx_installer.cc

@@ -524,7 +524,7 @@ void CrxInstaller::OnUnpackSuccess(
   extension_ = extension;
   temp_dir_ = temp_dir;
   ruleset_checksums_ = std::move(ruleset_checksums);
-  ReportInstallationStage(InstallationStage::kFinalizing);
+  ReportInstallationStage(InstallationStage::kCheckingExpectations);
 
   if (!install_icon.empty())
     install_icon_ = std::make_unique<SkBitmap>(install_icon);
@@ -722,7 +722,7 @@ void CrxInstaller::OnInstallChecksComplete(const PreloadCheck::Errors& errors) {
 
 void CrxInstaller::ConfirmInstall() {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
-  ReportInstallationStage(InstallationStage::kComplete);
+  ReportInstallationStage(InstallationStage::kFinalizing);
   ExtensionService* service = service_weak_.get();
   if (!service || service->browser_terminating())
     return;
@@ -1047,6 +1047,7 @@ void CrxInstaller::NotifyCrxInstallBegin() {
 
 void CrxInstaller::NotifyCrxInstallComplete(
     const base::Optional<CrxInstallError>& error) {
+  ReportInstallationStage(InstallationStage::kComplete);
   const std::string extension_id =
       expected_id_.empty() && extension() ? extension()->id() : expected_id_;
   InstallStageTracker* install_stage_tracker =

chrome/browser/extensions/forced_extensions/force_installed_metrics.cc

@@ -205,6 +205,30 @@ void ForceInstalledMetrics::ReportMetrics() {
             installation.unpacking_started_time.value() -
                 installation.copying_started_time.value());
       }
+      if (installation.checking_expectations_started_time) {
+        DCHECK(installation.unpacking_started_time);
+        base::UmaHistogramLongTimes(
+            "Extensions.ForceInstalledTime.UnpackingStartTo."
+            "CheckingExpectationsStart",
+            installation.checking_expectations_started_time.value() -
+                installation.unpacking_started_time.value());
+      }
+      if (installation.finalizing_started_time) {
+        DCHECK(installation.checking_expectations_started_time);
+        base::UmaHistogramLongTimes(
+            "Extensions.ForceInstalledTime.CheckingExpectationsStartTo."
+            "FinalizingStart",
+            installation.finalizing_started_time.value() -
+                installation.checking_expectations_started_time.value());
+      }
+      if (installation.installation_complete_time) {
+        DCHECK(installation.finalizing_started_time);
+        base::UmaHistogramLongTimes(
+            "Extensions.ForceInstalledTime.FinalizingStartTo."
+            "CRXInstallComplete",
+            installation.installation_complete_time.value() -
+                installation.finalizing_started_time.value());
+      }
     }
   }
   if (missing_forced_extensions.empty()) {

chrome/browser/extensions/forced_extensions/force_installed_metrics_unittest.cc

@@ -115,6 +115,12 @@ constexpr char kVerificationTimeStats[] =
     "Extensions.ForceInstalledTime.VerificationStartTo.CopyingStart";
 constexpr char kCopyingTimeStats[] =
     "Extensions.ForceInstalledTime.CopyingStartTo.UnpackingStart";
+constexpr char kUnpackingTimeStats[] =
+    "Extensions.ForceInstalledTime.UnpackingStartTo.CheckingExpectationsStart";
+constexpr char kCheckingExpectationsTimeStats[] =
+    "Extensions.ForceInstalledTime.CheckingExpectationsStartTo.FinalizingStart";
+constexpr char kFinalizingTimeStats[] =
+    "Extensions.ForceInstalledTime.FinalizingStartTo.CRXInstallComplete";
 
 }  // namespace
 
@@ -199,12 +205,9 @@ class ForceInstalledMetricsTest : public testing::Test,
 
   // Report downloading manifest stage for both the extensions.
   void ReportDownloadingManifestStage() {
-    auto ext1 = ExtensionBuilder(kExtensionName1).SetID(kExtensionId1).Build();
     install_stage_tracker_->ReportDownloadingStage(
         kExtensionId1,
         ExtensionDownloaderDelegate::Stage::DOWNLOADING_MANIFEST);
-    tracker_->OnExtensionLoaded(profile_, ext1.get());
-    auto ext2 = ExtensionBuilder(kExtensionName2).SetID(kExtensionId2).Build();
     install_stage_tracker_->ReportDownloadingStage(
         kExtensionId2,
         ExtensionDownloaderDelegate::Stage::DOWNLOADING_MANIFEST);
@@ -340,6 +343,8 @@ TEST_F(ForceInstalledMetricsTest, ExtensionsManifestDownloadTime) {
   ReportDownloadingManifestStage();
   install_stage_tracker_->ReportDownloadingStage(
       kExtensionId1, ExtensionDownloaderDelegate::Stage::MANIFEST_LOADED);
+  auto ext1 = ExtensionBuilder(kExtensionName1).SetID(kExtensionId1).Build();
+  tracker_->OnExtensionLoaded(profile_, ext1.get());
   install_stage_tracker_->ReportFailure(
       kExtensionId2, InstallStageTracker::FailureReason::MANIFEST_INVALID);
   // ForceInstalledMetrics shuts down timer because all extension are either
@@ -354,6 +359,8 @@ TEST_F(ForceInstalledMetricsTest, ExtensionsCrxDownloadTime) {
   SetupForceList();
   ReportDownloadingManifestStage();
   ReportInstallationStarted();
+  auto ext1 = ExtensionBuilder(kExtensionName1).SetID(kExtensionId1).Build();
+  tracker_->OnExtensionLoaded(profile_, ext1.get());
   install_stage_tracker_->ReportFailure(
       kExtensionId2, InstallStageTracker::FailureReason::MANIFEST_INVALID);
   // ForceInstalledMetrics shuts down timer because all extension are either
@@ -372,6 +379,8 @@ TEST_F(ForceInstalledMetricsTest,
       kExtensionId1, ExtensionDownloaderDelegate::Stage::FINISHED);
   install_stage_tracker_->ReportInstallationStage(
       kExtensionId1, InstallStageTracker::Stage::INSTALLING);
+  auto ext1 = ExtensionBuilder(kExtensionName1).SetID(kExtensionId1).Build();
+  tracker_->OnExtensionLoaded(profile_, ext1.get());
   install_stage_tracker_->ReportFailure(
       kExtensionId2, InstallStageTracker::FailureReason::MANIFEST_INVALID);
   // ForceInstalledMetrics shuts down timer because all extension are either
@@ -393,6 +402,14 @@ TEST_F(ForceInstalledMetricsTest, ExtensionsReportInstallationStageTimes) {
       kExtensionId1, InstallationStage::kCopying);
   install_stage_tracker_->ReportCRXInstallationStage(
       kExtensionId1, InstallationStage::kUnpacking);
+  install_stage_tracker_->ReportCRXInstallationStage(
+      kExtensionId1, InstallationStage::kCheckingExpectations);
+  install_stage_tracker_->ReportCRXInstallationStage(
+      kExtensionId1, InstallationStage::kFinalizing);
+  install_stage_tracker_->ReportCRXInstallationStage(
+      kExtensionId1, InstallationStage::kComplete);
+  auto ext1 = ExtensionBuilder(kExtensionName1).SetID(kExtensionId1).Build();
+  tracker_->OnExtensionLoaded(profile_, ext1.get());
   install_stage_tracker_->ReportFailure(
       kExtensionId2, InstallStageTracker::FailureReason::MANIFEST_INVALID);
   // ForceInstalledMetrics shuts down timer because all extension are either
@@ -400,6 +417,9 @@ TEST_F(ForceInstalledMetricsTest, ExtensionsReportInstallationStageTimes) {
   EXPECT_FALSE(fake_timer_->IsRunning());
   histogram_tester_.ExpectTotalCount(kVerificationTimeStats, 1);
   histogram_tester_.ExpectTotalCount(kCopyingTimeStats, 1);
+  histogram_tester_.ExpectTotalCount(kUnpackingTimeStats, 1);
+  histogram_tester_.ExpectTotalCount(kCheckingExpectationsTimeStats, 1);
+  histogram_tester_.ExpectTotalCount(kFinalizingTimeStats, 1);
 }
 
 // Reporting disable reason for the force installed extensions which are

chrome/browser/extensions/forced_extensions/install_stage_tracker.cc

@@ -197,6 +197,12 @@ void InstallStageTracker::ReportCRXInstallationStage(const ExtensionId& id,
     data.copying_started_time = current_time;
   else if (stage == InstallationStage::kUnpacking)
     data.unpacking_started_time = current_time;
+  else if (stage == InstallationStage::kCheckingExpectations)
+    data.checking_expectations_started_time = current_time;
+  else if (stage == InstallationStage::kFinalizing)
+    data.finalizing_started_time = current_time;
+  else if (stage == InstallationStage::kComplete)
+    data.installation_complete_time = current_time;
 
   for (auto& observer : observers_) {
     observer.OnExtensionDataChangedForTesting(id, browser_context_, data);

chrome/browser/extensions/forced_extensions/install_stage_tracker.h

@@ -331,6 +331,14 @@ class InstallStageTracker : public KeyedService {
     base::Optional<base::TimeTicks> copying_started_time;
     // Time at which unpacking of the extension archive is started.
     base::Optional<base::TimeTicks> unpacking_started_time;
+    // Time at which the extension archive has been successfully unpacked and
+    // the expectation checks before extension installation are started.
+    base::Optional<base::TimeTicks> checking_expectations_started_time;
+    // Time at which the extension has passed the expectation checks and the
+    // installation is started.
+    base::Optional<base::TimeTicks> finalizing_started_time;
+    // Time at which the installation process is complete.
+    base::Optional<base::TimeTicks> installation_complete_time;
   };
 
   class Observer : public base::CheckedObserver {

extensions/browser/install_stage.h

@@ -15,9 +15,12 @@ enum class InstallationStage {
   kCopying = 1,
   // Extension archive is about to be unpacked.
   kUnpacking = 2,
-  // Final checks before the installation is finished.
-  kFinalizing = 3,
-  kComplete = 4,
+  // Performing the expectation checks before the installation can be started.
+  kCheckingExpectations = 3,
+  // Installation of unpacked extension is started.
+  kFinalizing = 4,
+  // Extension installation process is complete.
+  kComplete = 5,
 };
 
 }  // namespace extensions

tools/metrics/histograms/histograms.xml

@@ -203771,13 +203771,21 @@ regressions. -->
 </histogram_suffixes>
 
 <histogram_suffixes name="ExtensionInstallStages" separator=".">
+  <suffix name="CheckingExpectationsStartTo.FinalizingStart"
+      label="Time taken to perform the expectations checks to confirm that
+             the extension can be installed."/>
   <suffix name="CopyingStartTo.UnpackingStart"
       label="Time taken to complete copying of extension archive into the
              working directory"/>
   <suffix name="DownloadingStartTo.ManifestDownloadComplete"
       label="Time taken to complete download of update manifest"/>
+  <suffix name="FinalizingStartTo.CRXInstallComplete"
+      label="Time taken to complete the installation of the unpacked
+             extension."/>
   <suffix name="ManifestDownloadCompleteTo.CRXDownloadComplete"
       label="Time taken to complete download of CRX"/>
+  <suffix name="UnpackingStartTo.CheckingExpectationsStart"
+      label="Time taken to complete the unpacking of the extension archive."/>
   <suffix name="VerificationStartTo.CopyingStart"
       label="Time taken to complete signature verification of CRX"/>
   <affected-histogram name="Extensions.ForceInstalledTime"/>