ARC UMA: Add new histogram Arc.Provisioning.PreSignInTimeDelta

This newly added histogram accounts for the time delta from ARC
provisioning start to the time before GMS sign-in / CloudDPC
provisioning.

Bug: b:224637195
Test: Check chrome://histograms and see the new Arc.Provisioning.PreSignIn.TimeDelta after ARC provisioning
Change-Id: I6cd799095ba1f574d48628b7990cc749e1df8b95
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/3531291
Reviewed-by: Long Cheng <lgcheng@google.com>
Reviewed-by: Muhammad Hasan Khan <mhasank@chromium.org>
Reviewed-by: Shao-Chuan Lee <shaochuan@chromium.org>
Reviewed-by: Greg Kerr <kerrnel@chromium.org>
Reviewed-by: Yusuke Sato <yusukes@chromium.org>
Reviewed-by: Jana Grill <janagrill@google.com>
Reviewed-by: Roman Sorokin <rsorokin@chromium.org>
Commit-Queue: Yao Li <yaohuali@google.com>
Cr-Commit-Position: refs/heads/main@{#988756}

ash/components/arc/metrics/arc_metrics_service.cc

@@ -21,6 +21,7 @@
 #include "base/metrics/histogram_macros.h"
 #include "base/strings/strcat.h"
 #include "base/strings/string_util.h"
+#include "base/time/time.h"
 #include "chromeos/dbus/power_manager/idle.pb.h"
 #include "chromeos/dbus/session_manager/session_manager_client.h"
 #include "components/exo/wm_helper.h"
@@ -57,6 +58,10 @@ constexpr base::TimeDelta kRequestKillCountPeriod = base::Minutes(10);
 const char kPSIMemoryPressureSomeARC[] = "ChromeOS.CWP.PSIMemPressure.ArcSome";
 const char kPSIMemoryPressureFullARC[] = "ChromeOS.CWP.PSIMemPressure.ArcFull";
 
+// Provisioning pre-sign-in time delta histogram.
+constexpr char kProvisioningPreSignInTimeDelta[] =
+    "Arc.Provisioning.PreSignIn.TimeDelta";
+
 // Logs UMA enum values to facilitate finding feedback reports in Xamine.
 template <typename T>
 void LogStabilityUmaEnum(const std::string& name, T sample) {
@@ -148,6 +153,7 @@ ArcMetricsService::ArcMetricsService(content::BrowserContext* context,
     exo::WMHelper::GetInstance()->AddActivationObserver(this);
   ui::GamepadProviderOzone::GetInstance()->AddGamepadObserver(this);
 
+  DCHECK(StabilityMetricsManager::Get());
   StabilityMetricsManager::Get()->SetArcNativeBridgeType(
       NativeBridgeType::UNKNOWN);
 
@@ -424,7 +430,7 @@ void ArcMetricsService::ReportDnsQueryResult(mojom::ArcDnsQuery query,
   std::string metric_name =
       base::StrCat({"Arc.Net.DnsQuery.", DnsQueryToString(query)});
   if (!success)
-      VLOG(4) << metric_name << ": " << success;
+    VLOG(4) << metric_name << ": " << success;
   base::UmaHistogramBoolean(metric_name, success);
 }
 
@@ -613,6 +619,28 @@ void ArcMetricsService::ReportMemoryPressure(
       metrics::kMemPressureExclusiveMax, metrics::kMemPressureHistogramBuckets);
 }
 
+void ArcMetricsService::ReportProvisioningStartTime(
+    const base::TimeTicks& start_time,
+    const std::string& account_type_suffix) {
+  arc_provisioning_start_time_.emplace(start_time);
+  arc_provisioning_account_type_suffix_.emplace(account_type_suffix);
+}
+
+void ArcMetricsService::ReportProvisioningPreSignIn() {
+  if (arc_provisioning_start_time_.has_value() &&
+      arc_provisioning_account_type_suffix_.has_value()) {
+    base::UmaHistogramCustomTimes(
+        kProvisioningPreSignInTimeDelta +
+            arc_provisioning_account_type_suffix_.value(),
+        base::TimeTicks::Now() - arc_provisioning_start_time_.value(),
+        base::Seconds(1), base::Minutes(5), 50);
+    arc_provisioning_start_time_.reset();
+    arc_provisioning_account_type_suffix_.reset();
+  } else {
+    LOG(ERROR) << "PreSignIn reported without prior starting time";
+  }
+}
+
 void ArcMetricsService::OnWindowActivated(
     wm::ActivationChangeObserver::ActivationReason reason,
     aura::Window* gained_active,

ash/components/arc/metrics/arc_metrics_service.h

@@ -145,6 +145,7 @@ class ArcMetricsService : public KeyedService,
   void ReportDataRestore(mojom::DataRestoreStatus status,
                          int64_t duration_ms) override;
   void ReportMemoryPressure(const std::vector<uint8_t>& psiFile) override;
+  void ReportProvisioningPreSignIn() override;
 
   // wm::ActivationChangeObserver overrides.
   // Records to UMA when a user has interacted with an ARC app window.
@@ -191,6 +192,10 @@ class ArcMetricsService : public KeyedService,
 
   void set_prefs(PrefService* prefs) { prefs_ = prefs; }
 
+  // Record the starting time of ARC provisioning, for later use.
+  void ReportProvisioningStartTime(const base::TimeTicks& start_time,
+                                   const std::string& account_type_suffix);
+
  private:
   // Adapter to be able to also observe ProcessInstance events.
   class ProcessObserver : public ConnectionObserver<mojom::ProcessInstance> {
@@ -320,6 +325,10 @@ class ArcMetricsService : public KeyedService,
   PrefService* prefs_ = nullptr;
   std::unique_ptr<ArcMetricsAnr> metrics_anr_;
 
+  // For reporting Arc.Provisioning.PreSignInTimeDelta.
+  absl::optional<base::TimeTicks> arc_provisioning_start_time_;
+  absl::optional<std::string> arc_provisioning_account_type_suffix_;
+
   // Always keep this the last member of this class to make sure it's the
   // first thing to be destructed.
   base::WeakPtrFactory<ArcMetricsService> weak_ptr_factory_{this};

ash/components/arc/mojom/metrics.mojom

@@ -427,6 +427,10 @@ interface MetricsHost {
   // Reports raw memory pressure data, as the contents of /proc/pressure/memory.
   // This is invoked solely by ARCVM.
   [MinVersion=21] ReportMemoryPressure@23(array<uint8> psi_file_contents);
+
+  // Reports that ArcAppLauncher is about to start GMS sign-in / CloudDPC
+  // provisioning. This only happens during ARC provisioning.
+  [MinVersion=22] ReportProvisioningPreSignIn@24();
 };
 
 // Deprecated method IDs: 0

chrome/browser/ash/arc/intent_helper/arc_settings_service_unittest.cc

@@ -7,6 +7,9 @@
 #include <memory>
 
 #include "ash/components/arc/arc_prefs.h"
+#include "ash/components/arc/arc_util.h"
+#include "ash/components/arc/metrics/arc_metrics_service.h"
+#include "ash/components/arc/metrics/stability_metrics_manager.h"
 #include "ash/components/arc/session/arc_bridge_service.h"
 #include "ash/components/arc/session/arc_service_manager.h"
 #include "ash/components/arc/test/arc_util_test_support.h"
@@ -16,6 +19,7 @@
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "chrome/browser/ash/arc/arc_optin_uma.h"
+#include "chrome/browser/ash/arc/arc_util.h"
 #include "chrome/browser/ash/arc/session/arc_provisioning_result.h"
 #include "chrome/browser/ash/arc/session/arc_session_manager.h"
 #include "chrome/browser/ash/arc/test/test_arc_session_manager.h"
@@ -74,6 +78,16 @@ class ArcSettingsServiceTest : public BrowserWithTestWindowTest {
     BrowserWithTestWindowTest::SetUp();
     arc_service_manager_->set_browser_context(profile());
 
+    arc::prefs::RegisterLocalStatePrefs(local_state_.registry());
+    arc::StabilityMetricsManager::Initialize(&local_state_);
+
+    ArcMetricsService::GetForBrowserContextForTesting(profile())
+        ->SetHistogramNamer(
+            base::BindRepeating([](const std::string& base_name) {
+              return arc::GetHistogramNameByUserTypeForPrimaryProfile(
+                  base_name);
+            }));
+
     const AccountId account_id(AccountId::FromUserEmailGaiaId(
         profile()->GetProfileUserName(), "1234567890"));
     user_manager()->AddUser(account_id);
@@ -94,6 +108,7 @@ class ArcSettingsServiceTest : public BrowserWithTestWindowTest {
   }
 
   void TearDown() override {
+    arc::StabilityMetricsManager::Shutdown();
     arc_bridge_service()->intent_helper()->CloseInstance(
         &intent_helper_instance_);
     arc_bridge_service()->backup_settings()->CloseInstance(

chrome/browser/ash/arc/notification/arc_provision_notification_service_unittest.cc

@@ -8,6 +8,8 @@
 #include <utility>
 
 #include "ash/components/arc/arc_prefs.h"
+#include "ash/components/arc/metrics/arc_metrics_service.h"
+#include "ash/components/arc/metrics/stability_metrics_manager.h"
 #include "ash/components/arc/session/arc_service_manager.h"
 #include "ash/components/arc/test/arc_util_test_support.h"
 #include "ash/components/arc/test/fake_arc_session.h"
@@ -83,13 +85,17 @@ class ArcProvisionNotificationServiceTest : public BrowserWithTestWindowTest {
     // Create the service (normally handled by ArcServiceLauncher).
     ArcProvisionNotificationService::GetForBrowserContext(profile());
 
+    arc::prefs::RegisterLocalStatePrefs(local_state_.registry());
+    arc::StabilityMetricsManager::Initialize(&local_state_);
+
     const AccountId account_id(AccountId::FromUserEmailGaiaId(
         profile()->GetProfileUserName(), "1234567890"));
     GetFakeUserManager()->AddUser(account_id);
     GetFakeUserManager()->LoginUser(account_id);
   }
 
   void TearDown() override {
+    arc::StabilityMetricsManager::Shutdown();
     // The session manager has to be shutdown before the profile is destroyed so
     // it stops observing prefs, but can't be reset completely because some
     // profile keyed services call into it.
@@ -116,6 +122,7 @@ class ArcProvisionNotificationServiceTest : public BrowserWithTestWindowTest {
 
  private:
   user_manager::ScopedUserManager user_manager_enabler_;
+  TestingPrefServiceSimple local_state_;
 };
 
 }  // namespace

chrome/browser/ash/arc/session/arc_session_manager.cc

@@ -475,6 +475,19 @@ bool IsDlcRequired() {
       ash::switches::kEnableHoudiniDlc);
 }
 
+// Inform ArcMetricsServices about the starting time of ARC provisioning.
+void ReportProvisioningStartTime(const base::TimeTicks& start_time,
+                                 Profile* profile) {
+  ArcMetricsService* metrics_service =
+      ArcMetricsService::GetForBrowserContext(profile);
+  // metrics_service might be null in unit tests.
+  if (metrics_service) {
+    auto account_type_suffix = GetHistogramNameByUserType("", profile);
+    metrics_service->ReportProvisioningStartTime(start_time,
+                                                 account_type_suffix);
+  }
+}
+
 }  // namespace
 
 // This class is used to track statuses on OptIn flow. It is created in case ARC
@@ -1640,6 +1653,7 @@ void ArcSessionManager::MaybeStartTimer() {
 
   VLOG(1) << "Setup provisioning timer";
   sign_in_start_time_ = base::TimeTicks::Now();
+  ReportProvisioningStartTime(sign_in_start_time_, profile_);
   arc_sign_in_timer_.Start(
       FROM_HERE, GetArcSignInTimeout(),
       base::BindOnce(&ArcSessionManager::OnArcSignInTimeout,

chrome/browser/ash/policy/handlers/lock_to_single_user_manager_unittest.cc

@@ -6,6 +6,9 @@
 
 #include <memory>
 
+#include "ash/components/arc/arc_prefs.h"
+#include "ash/components/arc/metrics/arc_metrics_service.h"
+#include "ash/components/arc/metrics/stability_metrics_manager.h"
 #include "ash/components/arc/session/arc_service_manager.h"
 #include "ash/components/arc/test/arc_util_test_support.h"
 #include "ash/components/arc/test/fake_arc_session.h"
@@ -26,6 +29,7 @@
 #include "chromeos/dbus/userdataauth/fake_cryptohome_misc_client.h"
 #include "components/account_id/account_id.h"
 #include "components/policy/proto/chrome_device_policy.pb.h"
+#include "components/prefs/testing_pref_service.h"
 #include "components/user_manager/scoped_user_manager.h"
 
 namespace policy {
@@ -64,6 +68,9 @@ class LockToSingleUserManagerTest : public BrowserWithTestWindowTest {
             base::BindRepeating(arc::FakeArcSession::Create)));
 
     arc_service_manager_->set_browser_context(profile());
+    arc::prefs::RegisterLocalStatePrefs(local_state_.registry());
+    arc::StabilityMetricsManager::Initialize(&local_state_);
+    arc::ArcMetricsService::GetForBrowserContextForTesting(profile());
 
     // TODO(yusukes): Stop re-creating the client here.
     chromeos::ConciergeClient::Shutdown();
@@ -72,15 +79,25 @@ class LockToSingleUserManagerTest : public BrowserWithTestWindowTest {
   }
 
   void TearDown() override {
+    arc::StabilityMetricsManager::Shutdown();
     // lock_to_single_user_manager has to be cleaned up first due to implicit
     // dependency on ArcSessionManager.
     lock_to_single_user_manager_.reset();
 
     arc_session_manager_->Shutdown();
     arc_session_manager_.reset();
+
+    // Destruction order matters here.
+    //
+    // This line destroys profile, thus indirectly destroys
+    // ArcMetricsService, since profile owns keyed services, like
+    // ArcMetricsService. DTor of ArcMetricsService calls things in
+    // ArcBridgeService, which is owned by ArcServiceManager. Thus
+    // ArcServiceManager must still be alive at this line.
+    BrowserWithTestWindowTest::TearDown();
+
     arc_service_manager_->set_browser_context(nullptr);
     arc_service_manager_.reset();
-    BrowserWithTestWindowTest::TearDown();
     chromeos::CryptohomeMiscClient::Shutdown();
     chromeos::SeneschalClient::Shutdown();
     chromeos::ConciergeClient::Shutdown();
@@ -156,6 +173,7 @@ class LockToSingleUserManagerTest : public BrowserWithTestWindowTest {
   ash::SessionTerminationManager termination_manager_;
   std::unique_ptr<LockToSingleUserManager> lock_to_single_user_manager_;
   chromeos::FakeConciergeClient* fake_concierge_client_;
+  TestingPrefServiceSimple local_state_;
 };
 
 TEST_F(LockToSingleUserManagerTest, ArcSessionLockTest) {

tools/metrics/histograms/metadata/arc/histograms.xml

@@ -1479,6 +1479,20 @@ chromium-metrics-reviews@google.com.
   <token key="ArcUserTypes" variants="ArcUserTypes"/>
 </histogram>
 
+<histogram name="Arc.Provisioning.PreSignIn.TimeDelta{ArcUserTypes}" units="ms"
+    expires_after="2022-10-14">
+  <owner>yaohuali@google.com</owner>
+  <owner>mhasank@google.com</owner>
+  <owner>arc-commercial@google.com</owner>
+  <summary>
+    Elapsed time from the signing in process start to right before GMS sign-in
+    or CloudDPC provisioning. {ArcUserTypes}
+  </summary>
+  <token key="ArcUserTypes" variants="ArcUserTypes">
+    <variant name=""/>
+  </token>
+</histogram>
+
 <histogram name="Arc.Provisioning.SignInError{ArcUserTypes}"
     enum="ArcProvisioningSignInError" expires_after="2022-08-01">
   <owner>mhasank@google.com</owner>