KeyPermissionsManager: Record time taken to update key permissions

This CL extends KeyPermissionsManager to record:
- The time taken to successfully migrate key permissions to chaps.
- The time taken to successfully update chaps with the new ARC usage
  flags.

Bug: 1139855
Change-Id: I78b871f520963ff6bfa907ccc598786c2a5bd9e1
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2544975Reviewed-by: Pavol Marko <pmarko@chromium.org>
Reviewed-by: Jesse Doherty <jwd@chromium.org>
Commit-Queue: Omar Morsi <omorsi@google.com>
Cr-Commit-Position: refs/heads/master@{#828776}

chrome/browser/chromeos/platform_keys/key_permissions/key_permissions_manager_impl.cc

@@ -15,6 +15,7 @@
 #include "base/metrics/histogram_functions.h"
 #include "base/observer_list_types.h"
 #include "base/optional.h"
+#include "base/time/time.h"
 #include "chrome/browser/browser_process.h"
 #include "chrome/browser/chromeos/platform_keys/key_permissions/extension_key_permissions_service.h"
 #include "chrome/browser/chromeos/platform_keys/key_permissions/key_permissions.pb.h"
@@ -45,12 +46,24 @@ chromeos::platform_keys::KeyPermissionsManager*
 chromeos::platform_keys::KeyPermissionsManager* g_system_token_kpm_for_testing =
     nullptr;
 
+// The name of the histogram that counts the number of times the migration
+// started as well as the number of times it succeeded and failed.
 const char kMigrationStatusHistogramName[] =
     "ChromeOS.KeyPermissionsManager.Migration";
-
+// The name of the histogram that counts the number of times the arc usage flags
+// update started as well as the number of times it succeeded and failed.
 const char kArcUsageUpdateStatusHistogramName[] =
     "ChromeOS.KeyPermissionsManager.ArcUsageUpdate";
 
+// The name of the histogram that records the time taken to successfully migrate
+// key permissions to chaps.
+const char kMigrationTimeHistogramName[] =
+    "ChromeOS.KeyPermissionsManager.MigrationTime";
+// The name of the histogram that records the time taken to successfully update
+// chaps with the new ARC usage flags.
+const char kArcUsageUpdateTimeHistogramName[] =
+    "ChromeOS.KeyPermissionsManager.ArcUsageUpdateTime";
+
 // These values are logged to UMA. Entries should not be renumbered and
 // numeric values should never be reused. Please keep in sync with
 // MigrationStatus in src/tools/metrics/histograms/enums.xml.
@@ -100,6 +113,8 @@ void KeyPermissionsManagerImpl::KeyPermissionsInChapsUpdater::Update(
   DCHECK(!update_started_) << "Update called more than once for the same "
                               "updater instance.";
 
+  update_start_time_ = base::TimeTicks::Now();
+
   update_started_ = true;
   callback_ = std::move(callback);
 
@@ -123,7 +138,7 @@ void KeyPermissionsManagerImpl::KeyPermissionsInChapsUpdater::UpdateWithAllKeys(
 
 void KeyPermissionsManagerImpl::KeyPermissionsInChapsUpdater::UpdateNextKey() {
   if (public_key_spki_der_queue_.empty()) {
-    std::move(callback_).Run(Status::kSuccess);
+    OnUpdateFinished();
     return;
   }
 
@@ -133,6 +148,39 @@ void KeyPermissionsManagerImpl::KeyPermissionsInChapsUpdater::UpdateNextKey() {
   UpdatePermissionsForKey(public_key);
 }
 
+void KeyPermissionsManagerImpl::KeyPermissionsInChapsUpdater::
+    OnUpdateFinished() {
+  switch (mode_) {
+    case Mode::kMigratePermissionsFromPrefs: {
+      // For more information about choosing |min| and |max| for the histogram,
+      // please refer to:
+      // https://chromium.googlesource.com/chromium/src/tools/+/refs/heads/master/metrics/histograms/README.md#count-histograms_choosing-min-and-max
+      //
+      // For more information about choosing the number of |buckets| for the
+      // histogram, please refer to:
+      // https://chromium.googlesource.com/chromium/src/tools/+/refs/heads/master/metrics/histograms/README.md#count-histograms_choosing-number-of-buckets
+      base::UmaHistogramCustomTimes(
+          kMigrationTimeHistogramName,
+          /*sample=*/base::TimeTicks::Now() - update_start_time_,
+          /*min=*/base::TimeDelta::FromMilliseconds(1),
+          /*max=*/base::TimeDelta::FromMinutes(5),
+          /*buckets=*/50);
+      break;
+    }
+    case Mode::kUpdateArcUsageFlag: {
+      base::UmaHistogramCustomTimes(
+          kArcUsageUpdateTimeHistogramName,
+          /*sample=*/base::TimeTicks::Now() - update_start_time_,
+          /*min=*/base::TimeDelta::FromMilliseconds(1),
+          /*max=*/base::TimeDelta::FromMinutes(5),
+          /*buckets=*/50);
+      break;
+    }
+  }
+
+  std::move(callback_).Run(Status::kSuccess);
+}
+
 void KeyPermissionsManagerImpl::KeyPermissionsInChapsUpdater::
     UpdatePermissionsForKey(const std::string& public_key_spki_der) {
   switch (mode_) {

chrome/browser/chromeos/platform_keys/key_permissions/key_permissions_manager_impl.h

@@ -15,6 +15,7 @@
 #include "base/observer_list_types.h"
 #include "base/optional.h"
 #include "base/scoped_observer.h"
+#include "base/time/time.h"
 #include "chrome/browser/chromeos/platform_keys/key_permissions/arc_key_permissions_manager_delegate.h"
 #include "chrome/browser/chromeos/platform_keys/key_permissions/key_permissions_manager.h"
 #include "chrome/browser/chromeos/platform_keys/platform_keys.h"
@@ -68,6 +69,7 @@ class KeyPermissionsManagerImpl : public KeyPermissionsManager,
     void UpdateWithAllKeys(std::vector<std::string> public_key_spki_der_list,
                            Status keys_retrieval_status);
     void UpdateNextKey();
+    void OnUpdateFinished();
     void UpdatePermissionsForKey(const std::string& public_key_spki_der);
     void UpdatePermissionsForKeyWithCorporateFlag(
         const std::string& public_key_spki_der,
@@ -80,6 +82,9 @@ class KeyPermissionsManagerImpl : public KeyPermissionsManager,
     base::queue<std::string> public_key_spki_der_queue_;
     bool update_started_ = false;
     UpdateCallback callback_;
+    // The time when the Update() method was called.
+    base::TimeTicks update_start_time_;
+
     base::WeakPtrFactory<KeyPermissionsInChapsUpdater> weak_ptr_factory_{this};
   };
 

tools/metrics/histograms/histograms_xml/chromeos/histograms.xml

@@ -407,6 +407,16 @@ incoming reviews. Googlers can read more about this at go/gwsq-gerrit.
   </summary>
 </histogram>
 
+<histogram name="ChromeOS.KeyPermissionsManager.ArcUsageUpdateTime" units="ms"
+    expires_after="2021-06-01">
+  <owner>omorsi@google.com</owner>
+  <owner>pmarko@chromium.org</owner>
+  <summary>
+    Records the time taken to successfully update chaps with the new ARC usage
+    flags.
+  </summary>
+</histogram>
+
 <histogram name="ChromeOS.KeyPermissionsManager.Migration"
     enum="KeyPermissionsManagerMigrationStatus" expires_after="2021-04-01">
   <owner>omorsi@google.com</owner>
@@ -417,6 +427,15 @@ incoming reviews. Googlers can read more about this at go/gwsq-gerrit.
   </summary>
 </histogram>
 
+<histogram name="ChromeOS.KeyPermissionsManager.MigrationTime" units="ms"
+    expires_after="2021-06-01">
+  <owner>omorsi@google.com</owner>
+  <owner>pmarko@chromium.org</owner>
+  <summary>
+    Records the time taken to successfully migrate key permissions to chaps.
+  </summary>
+</histogram>
+
 <histogram name="ChromeOS.Lacros.OSChannel" enum="ChromeOSChannel"
     expires_after="2021-10-01">
   <owner>jamescook@chromium.org</owner>