Record UMA stats for auto-enrollment related times.

- Time from EULA acceptance to Sign-In screen;
- Time from Sign-In screen display to login completion;
- Time for auto-enrollment protocol to complete;
- Extra time for auto-enrollment protocol to complete, after login completion.

BUG=chromium-os:23063
TEST=Do auto-enrollment. about:histograms collected these metrics.


Review URL: http://codereview.chromium.org/9289015

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@119238 0039d316-1c4b-4281-b951-d872f2087c98

10 files changed, 108 insertions, 6 deletions

diff --git a/chrome/browser/chromeos/login/base_login_display_host.cc b/chrome/browser/chromeos/login/base_login_display_host.cc
index 71ebec7..b9ecf00 100644
--- a/chrome/browser/chromeos/login/base_login_display_host.cc
+++ b/chrome/browser/chromeos/login/base_login_display_host.cc
@@ -194,6 +194,13 @@ void BaseLoginDisplayHost::OnSessionStart() {
 #endif
 }
 
+void BaseLoginDisplayHost::OnCompleteLogin() {
+  // Cancelling the |auto_enrollment_client_| now allows it to determine whether
+  // its protocol finished before login was complete.
+  if (auto_enrollment_client_.get())
+    auto_enrollment_client_.release()->CancelAndDeleteSoon();
+}
+
 void BaseLoginDisplayHost::StartWizard(
     const std::string& first_screen_name,
     DictionaryValue* screen_parameters) {
diff --git a/chrome/browser/chromeos/login/base_login_display_host.h b/chrome/browser/chromeos/login/base_login_display_host.h
index ece22fc..9e39f2b 100644
--- a/chrome/browser/chromeos/login/base_login_display_host.h
+++ b/chrome/browser/chromeos/login/base_login_display_host.h
@@ -1,4 +1,4 @@
-// Copyright (c) 2011 The Chromium Authors. All rights reserved.
+// Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
@@ -53,6 +53,7 @@ class BaseLoginDisplayHost : public LoginDisplayHost,
 
   // LoginDisplayHost implementation:
   virtual void OnSessionStart() OVERRIDE;
+  virtual void OnCompleteLogin() OVERRIDE;
   virtual void StartWizard(
       const std::string& first_screen_name,
       DictionaryValue* screen_parameters) OVERRIDE;
diff --git a/chrome/browser/chromeos/login/existing_user_controller.cc b/chrome/browser/chromeos/login/existing_user_controller.cc
index 22506f1..f160b9f 100644
--- a/chrome/browser/chromeos/login/existing_user_controller.cc
+++ b/chrome/browser/chromeos/login/existing_user_controller.cc
@@ -11,6 +11,7 @@
 #include "base/command_line.h"
 #include "base/logging.h"
 #include "base/message_loop.h"
+#include "base/metrics/histogram.h"
 #include "base/string_util.h"
 #include "base/stringprintf.h"
 #include "base/utf_string_conversions.h"
@@ -152,6 +153,7 @@ ExistingUserController::ExistingUserController(LoginDisplayHost* host)
 }
 
 void ExistingUserController::Init(const UserList& users) {
+  time_init_ = base::Time::Now();
   UpdateLoginDisplay(users, true);
 
   LoginUtils::Get()->PrewarmAuthentication();
@@ -289,6 +291,11 @@ void ExistingUserController::SetDisplayEmail(const std::string& email) {
 
 void ExistingUserController::CompleteLogin(const std::string& username,
                                            const std::string& password) {
+  if (!time_init_.is_null()) {
+    base::TimeDelta delta = base::Time::Now() - time_init_;
+    UMA_HISTOGRAM_MEDIUM_TIMES("Login.PromptToCompleteLoginTime", delta);
+  }
+  host_->OnCompleteLogin();
   // Auto-enrollment must have made a decision by now. It's too late to enroll
   // if the protocol isn't done at this point.
   if (do_auto_enrollment_) {
diff --git a/chrome/browser/chromeos/login/existing_user_controller.h b/chrome/browser/chromeos/login/existing_user_controller.h
index 6050b3a..7b11cd2 100644
--- a/chrome/browser/chromeos/login/existing_user_controller.h
+++ b/chrome/browser/chromeos/login/existing_user_controller.h
@@ -14,6 +14,7 @@
 #include "base/memory/scoped_ptr.h"
 #include "base/memory/weak_ptr.h"
 #include "base/string16.h"
+#include "base/time.h"
 #include "base/timer.h"
 #include "chrome/browser/chromeos/login/login_display.h"
 #include "chrome/browser/chromeos/login/login_performer.h"
@@ -235,6 +236,10 @@ class ExistingUserController : public LoginDisplay::Delegate,
   // Callback to invoke to resume login, after auto-enrollment has completed.
   base::Closure resume_login_callback_;
 
+  // Time when the signin screen was first displayed. Used to measure the time
+  // from showing the screen until a successful login is performed.
+  base::Time time_init_;
+
   FRIEND_TEST_ALL_PREFIXES(ExistingUserControllerTest, NewUserLogin);
 
   DISALLOW_COPY_AND_ASSIGN(ExistingUserController);
diff --git a/chrome/browser/chromeos/login/existing_user_controller_browsertest.cc b/chrome/browser/chromeos/login/existing_user_controller_browsertest.cc
index 29663f4..a460ed7 100644
--- a/chrome/browser/chromeos/login/existing_user_controller_browsertest.cc
+++ b/chrome/browser/chromeos/login/existing_user_controller_browsertest.cc
@@ -64,6 +64,7 @@ class MockLoginDisplayHost : public LoginDisplayHost {
   MOCK_CONST_METHOD0(GetNativeWindow, gfx::NativeWindow(void));
   MOCK_CONST_METHOD0(GetWidget, views::Widget*(void));
   MOCK_METHOD0(OnSessionStart, void(void));
+  MOCK_METHOD0(OnCompleteLogin, void(void));
   MOCK_METHOD1(SetOobeProgressBarVisible, void(bool));
   MOCK_METHOD1(SetShutdownButtonEnabled, void(bool));
   MOCK_METHOD1(SetStatusAreaEnabled, void(bool));
diff --git a/chrome/browser/chromeos/login/login_display_host.h b/chrome/browser/chromeos/login/login_display_host.h
index f570bee..c1333c1 100644
--- a/chrome/browser/chromeos/login/login_display_host.h
+++ b/chrome/browser/chromeos/login/login_display_host.h
@@ -41,6 +41,9 @@ class LoginDisplayHost {
   // LoginDisplayHost instance may delete itself.
   virtual void OnSessionStart() = 0;
 
+  // Called when a login has completed successfully.
+  virtual void OnCompleteLogin() = 0;
+
   // Toggles OOBE progress bar visibility, the bar is hidden by default.
   virtual void SetOobeProgressBarVisible(bool visible) = 0;
 
diff --git a/chrome/browser/chromeos/login/wizard_controller.cc b/chrome/browser/chromeos/login/wizard_controller.cc
index e54f0c1..52ffa07 100644
--- a/chrome/browser/chromeos/login/wizard_controller.cc
+++ b/chrome/browser/chromeos/login/wizard_controller.cc
@@ -14,6 +14,7 @@
 #include "base/command_line.h"
 #include "base/file_util.h"
 #include "base/logging.h"
+#include "base/metrics/histogram.h"
 #include "base/threading/thread_restrictions.h"
 #include "chrome/browser/browser_process.h"
 #include "chrome/browser/chromeos/cros/cros_library.h"
@@ -247,6 +248,10 @@ void WizardController::ShowNetworkScreen() {
 }
 
 void WizardController::ShowLoginScreen() {
+  if (!time_eula_accepted_.is_null()) {
+    base::TimeDelta delta = base::Time::Now() - time_eula_accepted_;
+    UMA_HISTOGRAM_MEDIUM_TIMES("OOBE.EULAToSignInTime", delta);
+  }
   VLOG(1) << "Showing login screen.";
   SetStatusAreaVisible(true);
   host_->StartSignInScreen();
@@ -394,6 +399,7 @@ void WizardController::OnUpdateCompleted() {
 }
 
 void WizardController::OnEulaAccepted() {
+  time_eula_accepted_ = base::Time::Now();
   MarkEulaAccepted();
   bool enabled =
       OptionsUtil::ResolveMetricsReportingEnabled(usage_statistics_reporting_);
diff --git a/chrome/browser/chromeos/login/wizard_controller.h b/chrome/browser/chromeos/login/wizard_controller.h
index b8c6a8a..3c5fba0 100644
--- a/chrome/browser/chromeos/login/wizard_controller.h
+++ b/chrome/browser/chromeos/login/wizard_controller.h
@@ -1,4 +1,4 @@
-// Copyright (c) 2011 The Chromium Authors. All rights reserved.
+// Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
@@ -11,6 +11,7 @@
 #include "base/compiler_specific.h"
 #include "base/gtest_prod_util.h"
 #include "base/memory/scoped_ptr.h"
+#include "base/time.h"
 #include "base/timer.h"
 #include "chrome/browser/chromeos/login/screen_observer.h"
 #include "chrome/browser/chromeos/login/wizard_screen.h"
@@ -214,6 +215,10 @@ class WizardController : public ScreenObserver {
   // during wizard lifetime.
   bool usage_statistics_reporting_;
 
+  // Time when the EULA was accepted. Used to measure the duration from the EULA
+  // acceptance until the Sign-In screen is displayed.
+  base::Time time_eula_accepted_;
+
   FRIEND_TEST_ALL_PREFIXES(EnterpriseEnrollmentScreenTest, TestCancel);
   FRIEND_TEST_ALL_PREFIXES(WizardControllerFlowTest, Accelerators);
   friend class WizardControllerFlowTest;
diff --git a/chrome/browser/policy/auto_enrollment_client.cc b/chrome/browser/policy/auto_enrollment_client.cc
index ec5bf14..bab7298 100644
--- a/chrome/browser/policy/auto_enrollment_client.cc
+++ b/chrome/browser/policy/auto_enrollment_client.cc
@@ -6,7 +6,10 @@
 
 #include "base/bind.h"
 #include "base/command_line.h"
+#include "base/location.h"
 #include "base/logging.h"
+#include "base/message_loop_proxy.h"
+#include "base/metrics/histogram.h"
 #include "base/string_number_conversions.h"
 #include "chrome/browser/policy/browser_policy_connector.h"
 #include "chrome/browser/policy/device_management_service.h"
@@ -128,12 +131,14 @@ void AutoEnrollmentClient::Start() {
   // Drop the previous job and reset state.
   request_job_.reset();
   should_auto_enroll_ = false;
+  time_start_ = base::Time();  // reset to null.
 
   if (device_management_service_.get()) {
     if (serial_number_hash_.empty()) {
       LOG(ERROR) << "Failed to get the hash of the serial number, "
                  << "will not attempt to auto-enroll.";
     } else {
+      time_start_ = base::Time::Now();
       SendRequest(power_initial_);
       // Don't invoke the callback now.
       return;
@@ -141,13 +146,26 @@ void AutoEnrollmentClient::Start() {
   }
 
   // Auto-enrollment can't even start, so we're done.
-  completion_callback_.Run();
+  OnProtocolDone();
+}
+
+void AutoEnrollmentClient::CancelAndDeleteSoon() {
+  if (time_start_.is_null()) {
+    // The client isn't running, just delete it.
+    delete this;
+  } else {
+    // Client still running, but our owner isn't interested in the result
+    // anymore. Wait until the protocol completes to measure the extra time
+    // needed.
+    time_extra_start_ = base::Time::Now();
+    completion_callback_.Reset();
+  }
 }
 
 void AutoEnrollmentClient::SendRequest(int power) {
   if (power < 0 || power > power_limit_ || serial_number_hash_.empty()) {
     NOTREACHED();
-    completion_callback_.Run();
+    OnProtocolDone();
     return;
   }
 
@@ -179,7 +197,7 @@ void AutoEnrollmentClient::OnRequestCompletion(
     const em::DeviceManagementResponse& response) {
   if (status != DM_STATUS_SUCCESS || !response.has_auto_enrollment_response()) {
     LOG(ERROR) << "Auto enrollment error: " << status;
-    completion_callback_.Run();
+    OnProtocolDone();
     return;
   }
 
@@ -222,7 +240,7 @@ void AutoEnrollmentClient::OnRequestCompletion(
   }
 
   // Auto-enrollment done.
-  completion_callback_.Run();
+  OnProtocolDone();
 }
 
 bool AutoEnrollmentClient::IsSerialInProtobuf(
@@ -234,4 +252,36 @@ bool AutoEnrollmentClient::IsSerialInProtobuf(
   return false;
 }
 
+void AutoEnrollmentClient::OnProtocolDone() {
+  static const char* kProtocolTime = "Enterprise.AutoEnrollmentProtocolTime";
+  static const char* kExtraTime = "Enterprise.AutoEnrollmentExtraTime";
+  // The mininum time can't be 0, must be at least 1.
+  static const base::TimeDelta kMin = base::TimeDelta::FromMilliseconds(1);
+  static const base::TimeDelta kMax = base::TimeDelta::FromMinutes(5);
+  // However, 0 can still be sampled.
+  static const base::TimeDelta kZero = base::TimeDelta::FromMilliseconds(0);
+  static const int kBuckets = 50;
+
+  base::Time now = base::Time::Now();
+  if (!time_start_.is_null()) {
+    base::TimeDelta delta = now - time_start_;
+    UMA_HISTOGRAM_CUSTOM_TIMES(kProtocolTime, delta, kMin, kMax, kBuckets);
+    time_start_ = base::Time();
+  }
+  base::TimeDelta delta = kZero;
+  if (!time_extra_start_.is_null()) {
+    // CancelAndDeleteSoon() was invoked before.
+    delta = now - time_extra_start_;
+    base::MessageLoopProxy::current()->DeleteSoon(FROM_HERE, this);
+    time_extra_start_ = base::Time();
+  }
+  // This samples |kZero| when there was no need for extra time, so that we can
+  // measure the ratio of users that succeeded without needing a delay to the
+  // total users going through OOBE.
+  UMA_HISTOGRAM_CUSTOM_TIMES(kExtraTime, delta, kMin, kMax, kBuckets);
+
+  if (!completion_callback_.is_null())
+    completion_callback_.Run();
+}
+
 }  // namespace policy
diff --git a/chrome/browser/policy/auto_enrollment_client.h b/chrome/browser/policy/auto_enrollment_client.h
index 5bc8b2b..91846fd 100644
--- a/chrome/browser/policy/auto_enrollment_client.h
+++ b/chrome/browser/policy/auto_enrollment_client.h
@@ -12,6 +12,7 @@
 #include "base/callback.h"
 #include "base/compiler_specific.h"
 #include "base/memory/scoped_ptr.h"
+#include "base/time.h"
 #include "chrome/browser/policy/cloud_policy_constants.h"
 #include "third_party/protobuf/src/google/protobuf/repeated_field.h"
 
@@ -53,6 +54,10 @@ class AutoEnrollmentClient {
   // call can invoke the |completion_callback_| if errors occur.
   void Start();
 
+  // Cancels any pending requests. |completion_callback_| will not be invoked.
+  // |this| will delete itself.
+  void CancelAndDeleteSoon();
+
   // Returns true if the protocol completed successfully and determined that
   // this device should do enterprise enrollment.
   bool should_auto_enroll() const { return should_auto_enroll_; }
@@ -76,6 +81,10 @@ class AutoEnrollmentClient {
   bool IsSerialInProtobuf(
       const google::protobuf::RepeatedPtrField<std::string>& hashes);
 
+  // Invoked when the protocol completes. This invokes the callback and records
+  // some UMA metrics.
+  void OnProtocolDone();
+
   // Callback to invoke when the protocol completes.
   base::Closure completion_callback_;
 
@@ -106,6 +115,14 @@ class AutoEnrollmentClient {
   scoped_ptr<DeviceManagementService> device_management_service_;
   scoped_ptr<DeviceManagementRequestJob> request_job_;
 
+  // Times used to determine the duration of the protocol, and the extra time
+  // needed to complete after the signin was complete.
+  // If |time_start_| is not null, the protocol is still running.
+  // If |time_extra_start_| is not null, the protocol is still running but our
+  // owner has relinquished ownership.
+  base::Time time_start_;
+  base::Time time_extra_start_;
+
   DISALLOW_COPY_AND_ASSIGN(AutoEnrollmentClient);
 };