[settings logging] Add a timer to prevent volume logging spam.

If the user drags the volume slider, the volume is changed many times in quick succession. We are only interested in logging the final change, so this timer ensures that an event is only logged after a small pause.

Bug: 1014839
Change-Id: I102f1cc4b1309a5ef59dc943dd76055e9960d98e
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2063611
Commit-Queue: Rachel Wong <wrong@chromium.org>
Reviewed-by: Tony Yeoman <tby@chromium.org>
Cr-Commit-Position: refs/heads/master@{#742881}

ash/system/machine_learning/user_settings_event_logger.cc

@@ -171,13 +171,22 @@ void UserSettingsEventLogger::LogAccessibilityUkmEvent(
 
 void UserSettingsEventLogger::LogVolumeUkmEvent(const int previous_level,
                                                 const int current_level) {
+  if (!volume_timer_.IsRunning()) {
+    previous_volume_ = previous_level;
+  }
+  current_volume_ = current_level;
+  volume_timer_.Start(FROM_HERE, kSliderDelay, this,
+                      &UserSettingsEventLogger::OnVolumeTimerEnded);
+}
+
+void UserSettingsEventLogger::OnVolumeTimerEnded() {
   UserSettingsEvent settings_event;
   auto* const event = settings_event.mutable_event();
 
   event->set_setting_id(UserSettingsEvent::Event::VOLUME);
   event->set_setting_type(UserSettingsEvent::Event::QUICK_SETTINGS);
-  event->set_previous_value(previous_level);
-  event->set_current_value(current_level);
+  event->set_previous_value(previous_volume_);
+  event->set_current_value(current_volume_);
 
   settings_event.mutable_features()->set_is_playing_audio(is_playing_audio_);
 
@@ -191,7 +200,7 @@ void UserSettingsEventLogger::LogBrightnessUkmEvent(const int previous_level,
     previous_brightness_ = previous_level;
   }
   current_brightness_ = current_level;
-  brightness_timer_.Start(FROM_HERE, kBrightnessDelay, this,
+  brightness_timer_.Start(FROM_HERE, kSliderDelay, this,
                           &UserSettingsEventLogger::OnBrightnessTimerEnded);
 }
 

ash/system/machine_learning/user_settings_event_logger.h

@@ -16,8 +16,7 @@
 namespace ash {
 namespace ml {
 
-static constexpr base::TimeDelta kBrightnessDelay =
-    base::TimeDelta::FromSeconds(1);
+static constexpr base::TimeDelta kSliderDelay = base::TimeDelta::FromSeconds(1);
 
 // This class handles logging for settings changes that are initiated by the
 // user from the quick settings tray. Exported for tests.
@@ -82,17 +81,21 @@ class ASH_EXPORT UserSettingsEventLogger
   // Sends the given event to UKM.
   void SendToUkm(const UserSettingsEvent& event);
 
+  void OnVolumeTimerEnded();
   void OnBrightnessTimerEnded();
   void OnPresentingTimerEnded();
   void OnFullscreenTimerEnded();
 
-  // When the user drags the brightness slider, the logger will be called
-  // multiple times at small time increments. This timer is used so that a
-  // brightness UKM event is only logged after there has been a pause.
+  // When the user drags the brightness or volume slider, the logger will be
+  // called multiple times at small time increments. These timers are used so
+  // that a UKM event is only logged after there has been a pause.
+  base::OneShotTimer volume_timer_;
   base::OneShotTimer brightness_timer_;
-  // Level of brightness before the timer was started.
+  // Levels before the corresponding timer was started.
+  int previous_volume_;
   int previous_brightness_;
-  // Level of brightness as of the most recent brightness event.
+  // Levels as of the most recent event.
+  int current_volume_;
   int current_brightness_;
 
   base::OneShotTimer presenting_timer_;

ash/system/machine_learning/user_settings_event_logger_unittest.cc

@@ -109,10 +109,16 @@ class UserSettingsEventLoggerTest : public AshTestBase {
         ukm::builders::UserSettingsEvent::kEntryName);
   }
 
+  // Volume features are logged at the end of the timer delay.
+  void LogVolumeAndWait(const int previous_level, const int current_level) {
+    logger_->LogVolumeUkmEvent(previous_level, current_level);
+    task_environment_->FastForwardBy(kSliderDelay);
+  }
+
   // Brightness features are logged at the end of the timer delay.
-  void LogBrightnessAndWait(int previous_level, int current_level) {
+  void LogBrightnessAndWait(const int previous_level, const int current_level) {
     logger_->LogBrightnessUkmEvent(previous_level, current_level);
-    task_environment_->FastForwardBy(kBrightnessDelay);
+    task_environment_->FastForwardBy(kSliderDelay);
   }
 
   UserSettingsEventLogger* logger_;
@@ -305,12 +311,12 @@ TEST_F(UserSettingsEventLoggerTest, TestLogAccessibilityEvent) {
                                      UserSettingsEvent::Event::HIGH_CONTRAST);
 }
 
-TEST_F(UserSettingsEventLoggerTest, TestLogVolumeEvent) {
-  logger_->LogVolumeUkmEvent(23, 98);
+TEST_F(UserSettingsEventLoggerTest, TestLogVolumeFeatures) {
+  LogVolumeAndWait(23, 98);
   logger_->OnOutputStarted();
-  logger_->LogVolumeUkmEvent(0, 0);
+  LogVolumeAndWait(0, 0);
   logger_->OnOutputStopped();
-  logger_->LogVolumeUkmEvent(0, 0);
+  LogVolumeAndWait(0, 0);
 
   const auto& entries = GetUkmEntries();
   ASSERT_EQ(3ul, entries.size());
@@ -330,6 +336,29 @@ TEST_F(UserSettingsEventLoggerTest, TestLogVolumeEvent) {
   TestUkmRecorder::ExpectEntryMetric(entries[2], "IsPlayingAudio", false);
 }
 
+TEST_F(UserSettingsEventLoggerTest, TestVolumeDelay) {
+  // Only log an event if there is a pause of |kSliderDelay|.
+  logger_->LogVolumeUkmEvent(10, 11);
+  task_environment_->FastForwardBy(kSliderDelay / 2);
+  logger_->LogVolumeUkmEvent(11, 12);
+  logger_->LogVolumeUkmEvent(12, 13);
+  logger_->LogVolumeUkmEvent(13, 14);
+  task_environment_->FastForwardBy(kSliderDelay / 2);
+  logger_->LogVolumeUkmEvent(14, 15);
+  task_environment_->FastForwardBy(kSliderDelay);
+
+  const auto& entries = GetUkmEntries();
+  ASSERT_EQ(1ul, entries.size());
+
+  const auto* entry = entries[0];
+  TestUkmRecorder::ExpectEntryMetric(entry, "SettingId",
+                                     UserSettingsEvent::Event::VOLUME);
+  TestUkmRecorder::ExpectEntryMetric(entry, "SettingType",
+                                     UserSettingsEvent::Event::QUICK_SETTINGS);
+  TestUkmRecorder::ExpectEntryMetric(entry, "PreviousValue", 10);
+  TestUkmRecorder::ExpectEntryMetric(entry, "CurrentValue", 15);
+}
+
 TEST_F(UserSettingsEventLoggerTest, TestBrightnessFeatures) {
   LogBrightnessAndWait(12, 29);
 
@@ -340,7 +369,7 @@ TEST_F(UserSettingsEventLoggerTest, TestBrightnessFeatures) {
   // Exit fullscreen. |is_recently_fullscreen| should remain true for 5 minutes,
   // with 1 second given for leeway on either side.
   logger_->OnFullscreenStateChanged(false, nullptr);
-  FastForwardBySeconds(299 - kBrightnessDelay.InSeconds());
+  FastForwardBySeconds(299 - kSliderDelay.InSeconds());
   LogBrightnessAndWait(0, 0);
   FastForwardBySeconds(2);
   LogBrightnessAndWait(0, 0);
@@ -365,15 +394,15 @@ TEST_F(UserSettingsEventLoggerTest, TestBrightnessFeatures) {
 }
 
 TEST_F(UserSettingsEventLoggerTest, TestBrightnessDelay) {
-  // Only log an event if there is a pause of |kBrightnessDelay|.
+  // Only log an event if there is a pause of |kSliderDelay|.
   logger_->LogBrightnessUkmEvent(10, 11);
-  task_environment_->FastForwardBy(kBrightnessDelay / 2);
+  task_environment_->FastForwardBy(kSliderDelay / 2);
   logger_->LogBrightnessUkmEvent(11, 12);
   logger_->LogBrightnessUkmEvent(12, 13);
   logger_->LogBrightnessUkmEvent(13, 14);
-  task_environment_->FastForwardBy(kBrightnessDelay / 2);
+  task_environment_->FastForwardBy(kSliderDelay / 2);
   logger_->LogBrightnessUkmEvent(14, 15);
-  task_environment_->FastForwardBy(kBrightnessDelay);
+  task_environment_->FastForwardBy(kSliderDelay);
 
   const auto& entries = GetUkmEntries();
   ASSERT_EQ(1ul, entries.size());