CRAS: Log samples dropped of devices

Add UMA DeviceSamplesDropped.{Device_type} to log the number of samples
dropped.

BUG=b:333632030
TEST=Use stressapptest to tigger overrun and check the UMA logs.

Change-Id: Iaeab8a8b037545d316c4a31f4f678d8b3e21e6ef
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/third_party/adhd/+/5449641
Tested-by: chromeos-cop-builder@chromeos-cop.iam.gserviceaccount.com <chromeos-cop-builder@chromeos-cop.iam.gserviceaccount.com>
Reviewed-by: Li-Yu Yu <aaronyu@google.com>
Commit-Queue: Yu-Hsuan Hsu <yuhsuan@chromium.org>

11 files changed, 69 insertions, 0 deletions

diff --git a/cras/client/cras-sys/src/lib.rs b/cras/client/cras-sys/src/lib.rs
index 35c9f633..3ac69a16 100644
--- a/cras/client/cras-sys/src/lib.rs
+++ b/cras/client/cras-sys/src/lib.rs
@@ -400,6 +400,7 @@ impl Default for audio_dev_debug_info {
             num_underruns: 0,
             num_underruns_during_nc: 0,
             num_severe_underruns: 0,
+            num_samples_dropped: 0,
             highest_hw_level: 0,
             runtime_sec: 0,
             runtime_nsec: 0,
@@ -428,6 +429,7 @@ pub struct AudioDevDebugInfo {
     pub num_underruns: u32,
     pub num_underruns_during_nc: u32,
     pub num_severe_underruns: u32,
+    pub num_samples_dropped: u32,
     pub highest_hw_level: u32,
     #[serde(rename = "runtime_sec", serialize_with = "serialize_duration_secs")]
     pub runtime: Duration,
@@ -455,6 +457,7 @@ impl From<audio_dev_debug_info> for AudioDevDebugInfo {
             num_underruns: info.num_underruns,
             num_underruns_during_nc: info.num_underruns_during_nc,
             num_severe_underruns: info.num_severe_underruns,
+            num_samples_dropped: info.num_samples_dropped,
             highest_hw_level: info.highest_hw_level,
             runtime: Duration::new(info.runtime_sec.into(), info.runtime_nsec),
             longest_wake: Duration::new(info.longest_wake_sec.into(), info.longest_wake_nsec),
diff --git a/cras/deprecated/cras_test_client/cras_test_client.c b/cras/deprecated/cras_test_client/cras_test_client.c
index aff4a8ee..9666bc5c 100644
--- a/cras/deprecated/cras_test_client/cras_test_client.c
+++ b/cras/deprecated/cras_test_client/cras_test_client.c
@@ -1134,6 +1134,7 @@ static void print_aligned_audio_debug_info(const struct audio_debug_info* info,
         "num_underruns: %u\n"
         "num_underruns_during_nc: %u\n"
         "num_severe_underruns: %u\n"
+        "num_samples_dropped: %u\n"
         "highest_hw_level: %u\n"
         "runtime: %u.%09u\n"
         "longest_wake: %u.%09u\n"
@@ -1149,6 +1150,7 @@ static void print_aligned_audio_debug_info(const struct audio_debug_info* info,
         (unsigned int)info->devs[i].num_underruns,
         (unsigned int)info->devs[i].num_underruns_during_nc,
         (unsigned int)info->devs[i].num_severe_underruns,
+        (unsigned int)info->devs[i].num_samples_dropped,
         (unsigned int)info->devs[i].highest_hw_level,
         (unsigned int)info->devs[i].runtime_sec,
         (unsigned int)info->devs[i].runtime_nsec,
diff --git a/cras/include/cras_types.h b/cras/include/cras_types.h
index 00738c29..998db882 100644
--- a/cras/include/cras_types.h
+++ b/cras/include/cras_types.h
@@ -462,6 +462,7 @@ struct __attribute__((__packed__)) audio_dev_debug_info {
   uint32_t num_underruns;
   uint32_t num_underruns_during_nc;
   uint32_t num_severe_underruns;
+  uint32_t num_samples_dropped;
   uint32_t highest_hw_level;
   uint32_t runtime_sec;
   uint32_t runtime_nsec;
diff --git a/cras/src/server/audio_thread.c b/cras/src/server/audio_thread.c
index d74f6e13..2cadf3ce 100644
--- a/cras/src/server/audio_thread.c
+++ b/cras/src/server/audio_thread.c
@@ -514,6 +514,7 @@ static void append_dev_dump_info(struct audio_dev_debug_info* di,
   di->num_underruns_during_nc =
       cras_iodev_get_num_underruns_during_nc(adev->dev);
   di->num_severe_underruns = cras_iodev_get_num_severe_underruns(adev->dev);
+  di->num_samples_dropped = cras_iodev_get_num_samples_dropped(adev->dev);
   di->highest_hw_level = adev->dev->highest_hw_level;
   di->internal_gain_scaler = (adev->dev->direction == CRAS_STREAM_INPUT)
                                  ? adev->dev->internal_gain_scaler
diff --git a/cras/src/server/cras_iodev.c b/cras/src/server/cras_iodev.c
index 6cc5800f..ae547b45 100644
--- a/cras/src/server/cras_iodev.c
+++ b/cras/src/server/cras_iodev.c
@@ -1196,6 +1196,7 @@ int cras_iodev_open(struct cras_iodev* iodev,
   iodev->largest_cb_level = 0;
   iodev->num_underruns = 0;
   iodev->num_underruns_during_nc = 0;
+  iodev->num_samples_dropped = 0;
 
   iodev->reset_request_pending = 0;
   iodev->state = CRAS_IODEV_STATE_OPEN;
@@ -1807,6 +1808,11 @@ unsigned int cras_iodev_get_num_severe_underruns(
   return 0;
 }
 
+unsigned int cras_iodev_get_num_samples_dropped(
+    const struct cras_iodev* iodev) {
+  return iodev->num_samples_dropped;
+}
+
 int cras_iodev_reset_request(struct cras_iodev* iodev) {
   /* Ignore requests if there is a pending request.
    * This function sends the request from audio thread to main
@@ -2041,6 +2047,7 @@ static int cras_iodev_drop_frames(struct cras_iodev* iodev,
     rate_estimator_add_frames(iodev->rate_est, -frames);
   }
 
+  iodev->num_samples_dropped += dropped_frames;
   ATLOG(atlog, AUDIO_THREAD_DEV_DROP_FRAMES, iodev->info.idx, dropped_frames,
         0);
 
diff --git a/cras/src/server/cras_iodev.h b/cras/src/server/cras_iodev.h
index ef9e02e9..1addb76a 100644
--- a/cras/src/server/cras_iodev.h
+++ b/cras/src/server/cras_iodev.h
@@ -395,6 +395,8 @@ struct cras_iodev {
   unsigned int num_underruns;
   // Number of underruns while AP NC is running.
   unsigned int num_underruns_during_nc;
+  // Number of samples dropped.
+  unsigned int num_samples_dropped;
   double rate_est_underrun;
   // Timestamp of the last update to the reset quota.
   struct timespec last_reset_timeref;
@@ -900,6 +902,14 @@ unsigned int cras_iodev_get_num_underruns_during_nc(
 unsigned int cras_iodev_get_num_severe_underruns(
     const struct cras_iodev* iodev);
 
+/* Get number of samples dropped so far.
+ * Args:
+ *    iodev[in] - The device.
+ * Returns:
+ *    An unsigned int for number of samples dropped.
+ */
+unsigned int cras_iodev_get_num_samples_dropped(const struct cras_iodev* iodev);
+
 /* Get number of valid frames in the hardware buffer. The valid frames does
  * not include zero samples we filled with before.
  * Args:
diff --git a/cras/src/server/cras_server_metrics.c b/cras/src/server/cras_server_metrics.c
index a15a1b87..83c26407 100644
--- a/cras/src/server/cras_server_metrics.c
+++ b/cras/src/server/cras_server_metrics.c
@@ -43,6 +43,7 @@ const char kDeviceNoiseCancellationStatus[] =
     "Cras.DeviceNoiseCancellationStatus";
 const char kDeviceSampleFormat[] = "Cras.DeviceSampleFormat";
 const char kDeviceSampleRate[] = "Cras.DeviceSampleRate";
+const char kDeviceSamplesDropped[] = "Cras.DeviceSamplesDropped";
 const char kDeviceDspOffloadStatus[] = "Cras.DeviceDspOffloadStatus";
 const char kFetchDelayMilliSeconds[] = "Cras.FetchDelayMilliSeconds";
 const char kFetchDelayCount[] = "Cras.FetchDelayCount";
@@ -147,6 +148,7 @@ enum CRAS_SERVER_METRICS_TYPE {
   DEVICE_NOISE_CANCELLATION_STATUS,
   DEVICE_SAMPLE_FORMAT,
   DEVICE_SAMPLE_RATE,
+  DEVICE_SAMPLES_DROPPED,
   DEVICE_DSP_OFFLOAD_STATUS,
   DLC_MANAGER_STATUS,
   HIGHEST_DEVICE_DELAY_INPUT,
@@ -1195,6 +1197,29 @@ int cras_server_metrics_num_underruns_during_apnc(struct cras_iodev* iodev) {
   return 0;
 }
 
+int cras_server_metrics_device_samples_dropped(struct cras_iodev* iodev) {
+  struct cras_server_metrics_message msg = CRAS_MAIN_MESSAGE_INIT;
+  union cras_server_metrics_data data;
+  int err;
+
+  if (iodev->direction != CRAS_STREAM_INPUT) {
+    return 0;
+  }
+
+  data.device_data.value = cras_iodev_get_num_samples_dropped(iodev);
+  data.device_data.type = get_metrics_device_type(iodev);
+
+  init_server_metrics_msg(&msg, DEVICE_SAMPLES_DROPPED, data);
+  err = cras_server_metrics_message_send((struct cras_main_message*)&msg);
+  if (err < 0) {
+    syslog(LOG_WARNING,
+           "Failed to send metrics message: DEVICE_SAMPLES_DROPPED");
+    return err;
+  }
+
+  return 0;
+}
+
 // Logs the frequency of missed callback.
 static int cras_server_metrics_missed_cb_frequency(
     const struct cras_rstream* stream) {
@@ -2000,6 +2025,12 @@ static void handle_metrics_message(struct cras_main_message* msg, void* arg) {
     case DEVICE_SAMPLE_RATE:
       metrics_device_sample_rate(metrics_msg->data.device_data);
       break;
+    case DEVICE_SAMPLES_DROPPED:
+      log_histogram_each_level(
+          2, (unsigned)metrics_msg->data.device_data.value, 0, 2000000000, 50,
+          kDeviceSamplesDropped,
+          metrics_device_type_str(metrics_msg->data.device_data.type));
+      break;
     case DEVICE_DSP_OFFLOAD_STATUS:
       metrics_device_dsp_offload_status(metrics_msg->data.device_data);
       break;
diff --git a/cras/src/server/cras_server_metrics.h b/cras/src/server/cras_server_metrics.h
index e621a5a3..88860a77 100644
--- a/cras/src/server/cras_server_metrics.h
+++ b/cras/src/server/cras_server_metrics.h
@@ -154,6 +154,9 @@ int cras_server_metrics_device_sample_format(struct cras_iodev* iodev);
 // Logs the sample rate of a device.
 int cras_server_metrics_device_sample_rate(struct cras_iodev* iodev);
 
+// Logs the sample dropped of a device.
+int cras_server_metrics_device_samples_dropped(struct cras_iodev* iodev);
+
 // Logs the device type when cras clients request to set aec ref.
 int cras_server_metrics_set_aec_ref_device_type(struct cras_iodev* iodev);
 
diff --git a/cras/src/server/dev_io.c b/cras/src/server/dev_io.c
index dcb6556b..88b0042d 100644
--- a/cras/src/server/dev_io.c
+++ b/cras/src/server/dev_io.c
@@ -1490,6 +1490,8 @@ void dev_io_rm_open_dev(struct open_dev** odev_list,
     cras_server_metrics_num_underruns_during_apnc(dev_to_rm->dev);
   }
 
+  cras_server_metrics_device_samples_dropped(dev_to_rm->dev);
+
   // Metrics logs the delay of this device.
   cras_server_metrics_highest_device_delay(dev_to_rm->dev->highest_hw_level,
                                            dev_to_rm->dev->largest_cb_level,
diff --git a/cras/src/tests/metrics_stub.cc b/cras/src/tests/metrics_stub.cc
index fd05e524..3cf6410d 100644
--- a/cras/src/tests/metrics_stub.cc
+++ b/cras/src/tests/metrics_stub.cc
@@ -31,6 +31,10 @@ int cras_server_metrics_device_sample_rate(struct cras_iodev* iodev) {
   return 0;
 }
 
+int cras_server_metrics_device_samples_dropped(struct cras_iodev* iodev) {
+  return 0;
+}
+
 int cras_server_metrics_device_configure_time(struct cras_iodev* iodev,
                                               struct timespec* beg,
                                               struct timespec* end) {
diff --git a/cras/src/tests/server_metrics_unittest.cc b/cras/src/tests/server_metrics_unittest.cc
index 1f666277..c57593d2 100644
--- a/cras/src/tests/server_metrics_unittest.cc
+++ b/cras/src/tests/server_metrics_unittest.cc
@@ -586,5 +586,10 @@ unsigned int cras_iodev_get_num_underruns_during_nc(
   return iodev->num_underruns_during_nc;
 }
 
+unsigned int cras_iodev_get_num_samples_dropped(
+    const struct cras_iodev* iodev) {
+  return iodev->num_samples_dropped;
+}
+
 }  // extern "C"
 }  // namespace