Log event time in UKM.

This event time is the elapsed time as measured from the moment an
idle event is received (and we start logging features) to the moment
when final event type is known (and we complete the event logging).

When logging the value to UKM, we bucket it exponentially such that if
the duration is
1. <1min: log its original value in sec.
2. <5min: bucket it to the nearest 10sec and log.
3. <10min: bucket it to the nearest 20sec and log.
4. >=10min: cap it at 10min (600sec).

Change-Id: I114592b07864af3840e5bae4a8ccd3dcc326f735
Bug: 784232
Reviewed-on: https://chromium-review.googlesource.com/867793Reviewed-by: Steven Holte <holte@chromium.org>
Reviewed-by: Dan Erat <derat@chromium.org>
Commit-Queue: Jia Meng <jiameng@chromium.org>
Cr-Commit-Position: refs/heads/master@{#529977}

chrome/browser/chromeos/power/ml/user_activity_event.proto

@@ -48,6 +48,11 @@ message UserActivityEvent {
       IDLE_SLEEP = 9;
     }
     optional Reason reason = 2;
+
+    // Time taken in seconds from when we start logging the features to the
+    // moment when the event type is known and we finish logging the complete
+    // event.
+    optional int32 log_duration_sec = 3;
   }
 
   message Features {

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

@@ -4,6 +4,7 @@
 
 #include "chrome/browser/chromeos/power/ml/user_activity_logger.h"
 
+#include "base/time/default_clock.h"
 #include "base/timer/timer.h"
 #include "chromeos/dbus/power_manager/power_supply_properties.pb.h"
 #include "chromeos/system/devicetype.h"
@@ -22,7 +23,8 @@ UserActivityLogger::UserActivityLogger(
     session_manager::SessionManager* session_manager,
     viz::mojom::VideoDetectorObserverRequest request,
     const chromeos::ChromeUserManager* user_manager)
-    : logger_delegate_(delegate),
+    : clock_(std::make_unique<base::DefaultClock>()),
+      logger_delegate_(delegate),
       idle_event_observer_(this),
       user_activity_observer_(this),
       power_manager_client_observer_(this),
@@ -119,7 +121,7 @@ void UserActivityLogger::OnVideoActivityStarted() {
 
 void UserActivityLogger::OnIdleEventObserved(
     const IdleEventNotifier::ActivityData& activity_data) {
-  idle_event_observed_ = true;
+  idle_event_start_ = clock_->Now();
   ExtractFeatures(activity_data);
 }
 
@@ -165,11 +167,11 @@ void UserActivityLogger::ExtractFeatures(
 
   if (!activity_data.last_mouse_time.is_null()) {
     features_.set_time_since_last_mouse_sec(
-        (base::Time::Now() - activity_data.last_mouse_time).InSeconds());
+        (clock_->Now() - activity_data.last_mouse_time).InSeconds());
   }
   if (!activity_data.last_key_time.is_null()) {
     features_.set_time_since_last_key_sec(
-        (base::Time::Now() - activity_data.last_key_time).InSeconds());
+        (clock_->Now() - activity_data.last_key_time).InSeconds());
   }
 
   features_.set_recent_time_active_sec(
@@ -216,7 +218,7 @@ void UserActivityLogger::ExtractFeatures(
 void UserActivityLogger::MaybeLogEvent(
     UserActivityEvent::Event::Type type,
     UserActivityEvent::Event::Reason reason) {
-  if (!idle_event_observed_)
+  if (idle_event_start_.is_null())
     return;
   screen_idle_timer_.Stop();
   UserActivityEvent activity_event;
@@ -224,17 +226,20 @@ void UserActivityLogger::MaybeLogEvent(
   UserActivityEvent::Event* event = activity_event.mutable_event();
   event->set_type(type);
   event->set_reason(reason);
+  event->set_log_duration_sec((clock_->Now() - idle_event_start_).InSeconds());
 
   *activity_event.mutable_features() = features_;
 
   // Log to metrics.
   logger_delegate_->LogActivity(activity_event);
-  idle_event_observed_ = false;
+  idle_event_start_ = base::Time();
 }
 
 void UserActivityLogger::SetTaskRunnerForTesting(
-    scoped_refptr<base::SequencedTaskRunner> task_runner) {
+    scoped_refptr<base::SequencedTaskRunner> task_runner,
+    std::unique_ptr<base::Clock> test_clock) {
   screen_idle_timer_.SetTaskRunner(task_runner);
+  clock_ = std::move(test_clock);
 }
 
 }  // namespace ml

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

@@ -23,6 +23,10 @@
 #include "ui/base/user_activity/user_activity_detector.h"
 #include "ui/base/user_activity/user_activity_observer.h"
 
+namespace base {
+class Clock;
+}
+
 namespace chromeos {
 namespace power {
 namespace ml {
@@ -84,10 +88,13 @@ class UserActivityLogger : public ui::UserActivityObserver,
 
   // Set the task runner for testing purpose.
   void SetTaskRunnerForTesting(
-      scoped_refptr<base::SequencedTaskRunner> task_runner);
+      scoped_refptr<base::SequencedTaskRunner> task_runner,
+      std::unique_ptr<base::Clock> test_clock);
 
-  // Flag indicating whether an idle event has been observed.
-  bool idle_event_observed_ = false;
+  // Time when an idle event is received and we start logging. Null if an idle
+  // event hasn't been observed.
+  // TODO(jiameng): replace it by base::TimeTicks (http://crbug.com/802942).
+  base::Time idle_event_start_;
 
   chromeos::PowerManagerClient::LidState lid_state_ =
       chromeos::PowerManagerClient::LidState::NOT_PRESENT;
@@ -110,6 +117,9 @@ class UserActivityLogger : public ui::UserActivityObserver,
   // Features extracted when receives an idle event.
   UserActivityEvent::Features features_;
 
+  // It is base::DefaultClock, but will be set to a mock clock for tests.
+  std::unique_ptr<base::Clock> clock_;
+
   UserActivityLoggerDelegate* const logger_delegate_;
 
   ScopedObserver<IdleEventNotifier, IdleEventNotifier::Observer>

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

@@ -28,6 +28,22 @@ int UserActivityLoggerDelegateUkm::BucketEveryFivePercents(int original_value) {
   return 5 * (original_value / 5);
 }
 
+int UserActivityLoggerDelegateUkm::ExponentiallyBucketTimestamp(
+    int timestamp_sec) {
+  DCHECK_GE(timestamp_sec, 0);
+  if (timestamp_sec < 60)
+    return timestamp_sec;
+
+  if (timestamp_sec < 300) {
+    return 10 * (timestamp_sec / 10);
+  }
+
+  if (timestamp_sec < 600) {
+    return 20 * (timestamp_sec / 20);
+  }
+  return 600;
+}
+
 UserActivityLoggerDelegateUkm::UserActivityLoggerDelegateUkm()
     : ukm_recorder_(ukm::UkmRecorder::Get()) {}
 
@@ -93,6 +109,8 @@ void UserActivityLoggerDelegateUkm::LogActivity(
   ukm::builders::UserActivity user_activity(source_id);
   user_activity.SetEventType(event.event().type())
       .SetEventReason(event.event().reason())
+      .SetEventLogDuration(
+          ExponentiallyBucketTimestamp(event.event().log_duration_sec()))
       .SetLastActivityTime(
           std::floor(event.features().last_activity_time_sec() / 3600))
       .SetLastActivityDay(event.features().last_activity_day())

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

@@ -24,6 +24,14 @@ class UserActivityLoggerDelegateUkm : public UserActivityLoggerDelegate {
   // |original_value| should be in the range of [0, 100].
   static int BucketEveryFivePercents(int original_value);
 
+  // Bucket |timestamp_sec| such that
+  // 1. if |timestamp_sec| < 60sec, return original value.
+  // 2. if |timestamp_sec| < 5min, bucket to nearest 10sec.
+  // 3. if |timestamp_sec| < 10min, bucket to nearest 20sec.
+  // 4. if |timestamp_sec| >= 10min, cap it at 10min.
+  // In all cases, the returned value is in seconds.
+  static int ExponentiallyBucketTimestamp(int timestamp_sec);
+
   UserActivityLoggerDelegateUkm();
   ~UserActivityLoggerDelegateUkm() override;
 

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

@@ -35,6 +35,7 @@ class UserActivityLoggerDelegateUkmTest : public TabActivityTestBase {
     UserActivityEvent::Event* event = user_activity_event_.mutable_event();
     event->set_type(UserActivityEvent::Event::REACTIVATE);
     event->set_reason(UserActivityEvent::Event::USER_ACTIVITY);
+    event->set_log_duration_sec(395);
     UserActivityEvent::Features* features =
         user_activity_event_.mutable_features();
     features->set_last_activity_time_sec(7300);
@@ -113,6 +114,7 @@ class UserActivityLoggerDelegateUkmTest : public TabActivityTestBase {
   const UkmMetricMap user_activity_values_ = {
       {UserActivity::kEventTypeName, 1},    // REACTIVATE
       {UserActivity::kEventReasonName, 1},  // USER_ACTIVITY
+      {UserActivity::kEventLogDurationName, 380},
       {UserActivity::kLastActivityTimeName, 2},
       {UserActivity::kLastUserActivityTimeName, 1},
       {UserActivity::kLastActivityDayName, 1},  // MON
@@ -130,7 +132,7 @@ class UserActivityLoggerDelegateUkmTest : public TabActivityTestBase {
   DISALLOW_COPY_AND_ASSIGN(UserActivityLoggerDelegateUkmTest);
 };
 
-TEST_F(UserActivityLoggerDelegateUkmTest, CheckValues) {
+TEST_F(UserActivityLoggerDelegateUkmTest, BucketEveryFivePercents) {
   const std::vector<int> original_values = {0, 14, 15, 100};
   const std::vector<int> buckets = {0, 10, 15, 100};
   for (size_t i = 0; i < original_values.size(); ++i) {
@@ -140,6 +142,18 @@ TEST_F(UserActivityLoggerDelegateUkmTest, CheckValues) {
   }
 }
 
+TEST_F(UserActivityLoggerDelegateUkmTest, ExponentiallyBucketTimestamp) {
+  const std::vector<int> original_values = {0,   18,  59,  60,  62,  69,  72,
+                                            299, 300, 306, 316, 599, 600, 602};
+  const std::vector<int> buckets = {0,   18,  59,  60,  60,  60,  70,
+                                    290, 300, 300, 300, 580, 600, 600};
+  for (size_t i = 0; i < original_values.size(); ++i) {
+    EXPECT_EQ(buckets[i],
+              UserActivityLoggerDelegateUkm::ExponentiallyBucketTimestamp(
+                  original_values[i]));
+  }
+}
+
 TEST_F(UserActivityLoggerDelegateUkmTest, Basic) {
   std::unique_ptr<Browser> browser =
       CreateTestBrowser(true /* is_visible */, true /* is_focused */);

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

@@ -8,6 +8,7 @@
 #include <vector>
 
 #include "base/test/test_mock_time_task_runner.h"
+#include "base/time/clock.h"
 #include "base/timer/timer.h"
 #include "chrome/browser/chromeos/login/users/fake_chrome_user_manager.h"
 #include "chrome/browser/chromeos/power/ml/idle_event_notifier.h"
@@ -29,6 +30,7 @@ void EqualEvent(const UserActivityEvent::Event& expected_event,
                 const UserActivityEvent::Event& result_event) {
   EXPECT_EQ(expected_event.type(), result_event.type());
   EXPECT_EQ(expected_event.reason(), result_event.reason());
+  EXPECT_EQ(expected_event.log_duration_sec(), result_event.log_duration_sec());
 }
 
 // Testing logger delegate.
@@ -71,7 +73,8 @@ class UserActivityLoggerTest : public testing::Test {
         &delegate_, idle_event_notifier_.get(), &user_activity_detector_,
         &fake_power_manager_client_, &session_manager_,
         mojo::MakeRequest(&observer), &fake_user_manager_);
-    activity_logger_->SetTaskRunnerForTesting(task_runner_);
+    activity_logger_->SetTaskRunnerForTesting(task_runner_,
+                                              task_runner_->GetMockClock());
   }
 
   ~UserActivityLoggerTest() override = default;
@@ -139,8 +142,9 @@ class UserActivityLoggerTest : public testing::Test {
 // UserActivityEvent.
 TEST_F(UserActivityLoggerTest, LogAfterIdleEvent) {
   // Trigger an idle event.
-  base::Time now = base::Time::UnixEpoch();
+  base::Time now = GetTaskRunner()->Now();
   ReportIdleEvent({now, now});
+  GetTaskRunner()->FastForwardBy(base::TimeDelta::FromSeconds(2));
   ReportUserActivity(nullptr);
 
   const std::vector<UserActivityEvent>& events = delegate_.events();
@@ -149,6 +153,7 @@ TEST_F(UserActivityLoggerTest, LogAfterIdleEvent) {
   UserActivityEvent::Event expected_event;
   expected_event.set_type(UserActivityEvent::Event::REACTIVATE);
   expected_event.set_reason(UserActivityEvent::Event::USER_ACTIVITY);
+  expected_event.set_log_duration_sec(2);
   EqualEvent(expected_event, events[0].event());
 }
 
@@ -167,7 +172,7 @@ TEST_F(UserActivityLoggerTest, LogBeforeIdleEvent) {
 TEST_F(UserActivityLoggerTest, LogSecondEvent) {
   ReportUserActivity(nullptr);
   // Trigger an idle event.
-  base::Time now = base::Time::UnixEpoch();
+  base::Time now = GetTaskRunner()->Now();
   ReportIdleEvent({now, now});
   // Another user event.
   ReportUserActivity(nullptr);
@@ -178,39 +183,49 @@ TEST_F(UserActivityLoggerTest, LogSecondEvent) {
   UserActivityEvent::Event expected_event;
   expected_event.set_type(UserActivityEvent::Event::REACTIVATE);
   expected_event.set_reason(UserActivityEvent::Event::USER_ACTIVITY);
+  expected_event.set_log_duration_sec(0);
   EqualEvent(expected_event, events[0].event());
 }
 
 // Log multiple events.
 TEST_F(UserActivityLoggerTest, LogMultipleEvents) {
   // Trigger an idle event.
-  base::Time now = base::Time::UnixEpoch();
+  base::Time now = GetTaskRunner()->Now();
   ReportIdleEvent({now, now});
   // First user event.
   ReportUserActivity(nullptr);
 
   // Trigger an idle event.
-  now = base::Time::UnixEpoch();
+  now = GetTaskRunner()->Now();
   ReportIdleEvent({now, now});
   // Second user event.
+  GetTaskRunner()->FastForwardBy(base::TimeDelta::FromSeconds(2));
   ReportUserActivity(nullptr);
 
   const std::vector<UserActivityEvent>& events = delegate_.events();
   ASSERT_EQ(2U, events.size());
 
-  UserActivityEvent::Event expected_event;
-  expected_event.set_type(UserActivityEvent::Event::REACTIVATE);
-  expected_event.set_reason(UserActivityEvent::Event::USER_ACTIVITY);
-  EqualEvent(expected_event, events[0].event());
-  EqualEvent(expected_event, events[1].event());
+  UserActivityEvent::Event expected_event1;
+  expected_event1.set_type(UserActivityEvent::Event::REACTIVATE);
+  expected_event1.set_reason(UserActivityEvent::Event::USER_ACTIVITY);
+  expected_event1.set_log_duration_sec(0);
+
+  UserActivityEvent::Event expected_event2;
+  expected_event2.set_type(UserActivityEvent::Event::REACTIVATE);
+  expected_event2.set_reason(UserActivityEvent::Event::USER_ACTIVITY);
+  expected_event2.set_log_duration_sec(2);
+
+  EqualEvent(expected_event1, events[0].event());
+  EqualEvent(expected_event2, events[1].event());
 }
 
 TEST_F(UserActivityLoggerTest, UserCloseLid) {
   ReportLidEvent(chromeos::PowerManagerClient::LidState::OPEN);
   // Trigger an idle event.
-  base::Time now = base::Time::UnixEpoch();
+  base::Time now = GetTaskRunner()->Now();
   ReportIdleEvent({now, now});
 
+  GetTaskRunner()->FastForwardBy(base::TimeDelta::FromSeconds(2));
   ReportLidEvent(chromeos::PowerManagerClient::LidState::CLOSED);
   const auto& events = delegate_.events();
   ASSERT_EQ(1U, events.size());
@@ -218,13 +233,14 @@ TEST_F(UserActivityLoggerTest, UserCloseLid) {
   UserActivityEvent::Event expected_event;
   expected_event.set_type(UserActivityEvent::Event::OFF);
   expected_event.set_reason(UserActivityEvent::Event::LID_CLOSED);
+  expected_event.set_log_duration_sec(2);
   EqualEvent(expected_event, events[0].event());
 }
 
 TEST_F(UserActivityLoggerTest, PowerChangeActivity) {
   ReportPowerChangeEvent(power_manager::PowerSupplyProperties::AC, 23.0f);
   // Trigger an idle event.
-  base::Time now = base::Time::UnixEpoch();
+  base::Time now = GetTaskRunner()->Now();
   ReportIdleEvent({now, now});
 
   // We don't care about battery percentage change, but only power source.
@@ -237,12 +253,13 @@ TEST_F(UserActivityLoggerTest, PowerChangeActivity) {
   UserActivityEvent::Event expected_event;
   expected_event.set_type(UserActivityEvent::Event::REACTIVATE);
   expected_event.set_reason(UserActivityEvent::Event::POWER_CHANGED);
+  expected_event.set_log_duration_sec(0);
   EqualEvent(expected_event, events[0].event());
 }
 
 TEST_F(UserActivityLoggerTest, VideoActivity) {
   // Trigger an idle event.
-  base::Time now = base::Time::UnixEpoch();
+  base::Time now = GetTaskRunner()->Now();
   ReportIdleEvent({now, now});
 
   ReportVideoStart();
@@ -252,12 +269,13 @@ TEST_F(UserActivityLoggerTest, VideoActivity) {
   UserActivityEvent::Event expected_event;
   expected_event.set_type(UserActivityEvent::Event::REACTIVATE);
   expected_event.set_reason(UserActivityEvent::Event::VIDEO_ACTIVITY);
+  expected_event.set_log_duration_sec(0);
   EqualEvent(expected_event, events[0].event());
 }
 
 TEST_F(UserActivityLoggerTest, SystemIdle) {
   // Trigger an idle event.
-  base::Time now = base::Time::UnixEpoch();
+  base::Time now = GetTaskRunner()->Now();
   ReportIdleEvent({now, now});
 
   ReportScreenIdle();
@@ -269,6 +287,8 @@ TEST_F(UserActivityLoggerTest, SystemIdle) {
   UserActivityEvent::Event expected_event;
   expected_event.set_type(UserActivityEvent::Event::TIMEOUT);
   expected_event.set_reason(UserActivityEvent::Event::SCREEN_OFF);
+  // Idle timeout is 10 seconds.
+  expected_event.set_log_duration_sec(10);
   EqualEvent(expected_event, events[0].event());
 }
 
@@ -276,7 +296,7 @@ TEST_F(UserActivityLoggerTest, SystemIdle) {
 // We should only observe user activity.
 TEST_F(UserActivityLoggerTest, SystemIdleInterrupted) {
   // Trigger an idle event.
-  base::Time now = base::Time::UnixEpoch();
+  base::Time now = GetTaskRunner()->Now();
   ReportIdleEvent({now, now});
 
   ReportScreenIdle();
@@ -291,12 +311,13 @@ TEST_F(UserActivityLoggerTest, SystemIdleInterrupted) {
   UserActivityEvent::Event expected_event;
   expected_event.set_type(UserActivityEvent::Event::REACTIVATE);
   expected_event.set_reason(UserActivityEvent::Event::USER_ACTIVITY);
+  expected_event.set_log_duration_sec(1);
   EqualEvent(expected_event, events[0].event());
 }
 
 TEST_F(UserActivityLoggerTest, ScreenLock) {
   // Trigger an idle event.
-  base::Time now = base::Time::UnixEpoch();
+  base::Time now = GetTaskRunner()->Now();
   ReportIdleEvent({now, now});
 
   ReportScreenLocked();
@@ -306,6 +327,7 @@ TEST_F(UserActivityLoggerTest, ScreenLock) {
   UserActivityEvent::Event expected_event;
   expected_event.set_type(UserActivityEvent::Event::OFF);
   expected_event.set_reason(UserActivityEvent::Event::SCREEN_LOCK);
+  expected_event.set_log_duration_sec(0);
   EqualEvent(expected_event, events[0].event());
 }
 

tools/metrics/ukm/ukm.xml

@@ -2289,6 +2289,13 @@ be describing additional metrics about the same event.
       |chromeos::power::ml::UserActivityEvent::Feature::DeviceType|
     </summary>
   </metric>
+  <metric name="EventLogDuration">
+    <summary>
+      Time taken in seconds from when we start logging the features to the
+      moment when the event type is known and we finish logging the complete
+      event.
+    </summary>
+  </metric>
   <metric name="EventReason">
     <summary>
       An enum representing the reason of the event, defined in