[Power: ML]: Add UMA logging for ML service Smart Dim calls

Add UMA logging of time taken to complete ML service requests,
as well as the time spent before a pending request is cancelled.
Also update the existing Smart Dim unit tests to verify that the logging
works.

Bug: 893425, 914640
Test: - Builds and boots, inference calls checked via logs on nocturne
      - All related unit tests still pass.

Change-Id: I542af752a0133939c65eaa435ed3f5be907140db
Reviewed-on: https://chromium-review.googlesource.com/c/1393670Reviewed-by: Jia Meng <jiameng@chromium.org>
Commit-Queue: Prashant Malani <pmalani@chromium.org>
Cr-Commit-Position: refs/heads/master@{#619892}

chrome/browser/chromeos/power/ml/user_activity_manager.cc

@@ -51,6 +51,14 @@ void LogPowerMLModelNoDimResult(FinalResult result) {
   UMA_HISTOGRAM_ENUMERATION("PowerML.ModelNoDim.Result", result);
 }
 
+void LogPowerMLSmartDimModelRequestCancel(base::TimeDelta time) {
+  UMA_HISTOGRAM_TIMES("PowerML.SmartDimModel.RequestCanceledDuration", time);
+}
+
+void LogPowerMLSmartDimModelRequestComplete(base::TimeDelta time) {
+  UMA_HISTOGRAM_TIMES("PowerML.SmartDimModel.RequestCompleteDuration", time);
+}
+
 void LogMetricsToUMA(const UserActivityEvent& event) {
   const FinalResult result =
       event.event().type() == UserActivityEvent::Event::REACTIVATE
@@ -262,6 +270,7 @@ void UserActivityManager::OnIdleEventObserved(
       base::FeatureList::IsEnabled(features::kUserActivityPrediction) &&
       smart_dim_model_) {
     waiting_for_model_decision_ = true;
+    time_dim_decision_requested_ = base::TimeTicks::Now();
     smart_dim_model_->RequestDimDecision(
         features_, base::Bind(&UserActivityManager::ApplyDimDecision,
                               weak_ptr_factory_.GetWeakPtr()));
@@ -273,6 +282,10 @@ void UserActivityManager::ApplyDimDecision(
     UserActivityEvent::ModelPrediction prediction) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
   waiting_for_model_decision_ = false;
+  const base::TimeDelta wait_time =
+      base::TimeTicks::Now() - time_dim_decision_requested_;
+  LogPowerMLSmartDimModelRequestComplete(wait_time);
+  time_dim_decision_requested_ = base::TimeTicks();
   // Only defer the dim if the model predicts so and also if the dim was not
   // previously deferred.
   if (prediction.response() == UserActivityEvent::ModelPrediction::NO_DIM &&
@@ -594,13 +607,15 @@ void UserActivityManager::ResetAfterLogging() {
 }
 
 void UserActivityManager::CancelDimDecisionRequest() {
-  // TODO(crbug.com/893425): Log the time after which a dim decision request
-  // was cancelled, in UMA.
   // TODO(crbug.com/893425): Add a unit-test to verify UMA logging of
   // cancellation time.
   LOG(WARNING) << "Cancelling pending Smart Dim decision request.";
   smart_dim_model_->CancelPreviousRequest();
   waiting_for_model_decision_ = false;
+  const base::TimeDelta wait_time =
+      base::TimeTicks::Now() - time_dim_decision_requested_;
+  LogPowerMLSmartDimModelRequestCancel(wait_time);
+  time_dim_decision_requested_ = base::TimeTicks();
 }
 
 }  // namespace ml

chrome/browser/chromeos/power/ml/user_activity_manager.h

@@ -242,6 +242,10 @@ class UserActivityManager : public ui::UserActivityObserver,
   // regarding whether to proceed with a dim or not. It is only set
   // to true in OnIdleEventObserved() when we request a dim decision.
   bool waiting_for_model_decision_ = false;
+  // Represents the time when a dim decision request was made. It is used to
+  // calculate time deltas while logging ML service dim decision request
+  // results.
+  base::TimeTicks time_dim_decision_requested_;
 
   // Model prediction for the current ScreenDimImminent event. Unset if
   // model prediction is disabled by an experiment.

chrome/browser/chromeos/power/ml/user_activity_manager_unittest.cc

@@ -11,6 +11,7 @@
 
 #include "base/cancelable_callback.h"
 #include "base/sequenced_task_runner.h"
+#include "base/test/metrics/histogram_tester.h"
 #include "base/test/scoped_feature_list.h"
 #include "base/test/scoped_task_environment.h"
 #include "base/time/clock.h"
@@ -892,6 +893,7 @@ TEST_F(UserActivityManagerTest, ScreenOffStateChanged) {
 }
 
 TEST_F(UserActivityManagerTest, ScreenDimDeferredWithFinalEvent) {
+  base::HistogramTester histogram_tester;
   const std::map<std::string, std::string> params = {
       {"dim_threshold", "0.651"}};
   base::test::ScopedFeatureList scoped_feature_list;
@@ -907,6 +909,9 @@ TEST_F(UserActivityManagerTest, ScreenDimDeferredWithFinalEvent) {
   ReportUserActivity(nullptr);
   EXPECT_EQ(1, GetNumberOfDeferredDims());
 
+  std::string histogram("PowerML.SmartDimModel.RequestCompleteDuration");
+  histogram_tester.ExpectTotalCount(histogram, 1);
+
   const std::vector<UserActivityEvent>& events = delegate_.events();
   ASSERT_EQ(1U, events.size());
 
@@ -928,6 +933,7 @@ TEST_F(UserActivityManagerTest, ScreenDimDeferredWithFinalEvent) {
 }
 
 TEST_F(UserActivityManagerTest, ScreenDimDeferredWithoutFinalEvent) {
+  base::HistogramTester histogram_tester;
   const std::map<std::string, std::string> params = {
       {"dim_threshold", "0.651"}};
   base::test::ScopedFeatureList scoped_feature_list;
@@ -942,11 +948,15 @@ TEST_F(UserActivityManagerTest, ScreenDimDeferredWithoutFinalEvent) {
   thread_bundle()->RunUntilIdle();
   EXPECT_EQ(1, GetNumberOfDeferredDims());
 
+  std::string histogram("PowerML.SmartDimModel.RequestCompleteDuration");
+  histogram_tester.ExpectTotalCount(histogram, 1);
+
   const std::vector<UserActivityEvent>& events = delegate_.events();
   EXPECT_TRUE(events.empty());
 }
 
 TEST_F(UserActivityManagerTest, ScreenDimNotDeferred) {
+  base::HistogramTester histogram_tester;
   const std::map<std::string, std::string> params = {
       {"dim_threshold", base::NumberToString(0.5)}};
   base::test::ScopedFeatureList scoped_feature_list;
@@ -962,6 +972,9 @@ TEST_F(UserActivityManagerTest, ScreenDimNotDeferred) {
   ReportUserActivity(nullptr);
   EXPECT_EQ(0, GetNumberOfDeferredDims());
 
+  std::string histogram("PowerML.SmartDimModel.RequestCompleteDuration");
+  histogram_tester.ExpectTotalCount(histogram, 1);
+
   const std::vector<UserActivityEvent>& events = delegate_.events();
   ASSERT_EQ(1U, events.size());
 
@@ -975,6 +988,7 @@ TEST_F(UserActivityManagerTest, ScreenDimNotDeferred) {
 }
 
 TEST_F(UserActivityManagerTest, TwoScreenDimImminentWithEventInBetween) {
+  base::HistogramTester histogram_tester;
   const std::map<std::string, std::string> params = {
       {"dim_threshold", base::NumberToString(0.5)}};
   base::test::ScopedFeatureList scoped_feature_list;
@@ -998,8 +1012,12 @@ TEST_F(UserActivityManagerTest, TwoScreenDimImminentWithEventInBetween) {
   model_.set_inactivity_score(20);
   thread_bundle()->FastForwardBy(base::TimeDelta::FromSeconds(10));
   ReportIdleEvent(data);
+  thread_bundle()->RunUntilIdle();
   EXPECT_EQ(1, GetNumberOfDeferredDims());
 
+  std::string histogram("PowerML.SmartDimModel.RequestCompleteDuration");
+  histogram_tester.ExpectTotalCount(histogram, 2);
+
   // Log when a SuspendImminent is received
   thread_bundle()->FastForwardBy(base::TimeDelta::FromSeconds(20));
   ReportSuspend(power_manager::SuspendImminent_Reason_IDLE,
@@ -1045,6 +1063,7 @@ TEST_F(UserActivityManagerTest, TwoScreenDimImminentWithEventInBetween) {
 }
 
 TEST_F(UserActivityManagerTest, TwoScreenDimImminentWithoutEventInBetween) {
+  base::HistogramTester histogram_tester;
   const std::map<std::string, std::string> params = {
       {"dim_threshold", base::NumberToString(0.5)}};
   base::test::ScopedFeatureList scoped_feature_list;
@@ -1066,6 +1085,9 @@ TEST_F(UserActivityManagerTest, TwoScreenDimImminentWithoutEventInBetween) {
   thread_bundle()->RunUntilIdle();
   EXPECT_EQ(1, GetNumberOfDeferredDims());
 
+  std::string histogram("PowerML.SmartDimModel.RequestCompleteDuration");
+  histogram_tester.ExpectTotalCount(histogram, 2);
+
   // Log when a SuspendImminent is received
   thread_bundle()->FastForwardBy(base::TimeDelta::FromSeconds(20));
   ReportSuspend(power_manager::SuspendImminent_Reason_IDLE,
@@ -1106,6 +1128,7 @@ TEST_F(UserActivityManagerTest, TwoScreenDimImminentWithoutEventInBetween) {
 }
 
 TEST_F(UserActivityManagerTest, ModelError) {
+  base::HistogramTester histogram_tester;
   const std::map<std::string, std::string> params = {
       {"dim_threshold", "0.651"}};
   base::test::ScopedFeatureList scoped_feature_list;
@@ -1122,6 +1145,9 @@ TEST_F(UserActivityManagerTest, ModelError) {
   ReportUserActivity(nullptr);
   EXPECT_EQ(0, GetNumberOfDeferredDims());
 
+  std::string histogram("PowerML.SmartDimModel.RequestCompleteDuration");
+  histogram_tester.ExpectTotalCount(histogram, 1);
+
   const std::vector<UserActivityEvent>& events = delegate_.events();
   ASSERT_EQ(1U, events.size());