Add delay and glitch stats for Windows audio capture.

Bug: 826664, 830624
Cq-Include-Trybots: luci.chromium.try:android_optional_gpu_tests_rel;luci.chromium.try:linux_optional_gpu_tests_rel;luci.chromium.try:mac_optional_gpu_tests_rel;master.tryserver.chromium.win:win_optional_gpu_tests_rel
Change-Id: I08e1ee4237f4e221baca4a0adec7a8bff19c1fa6
Reviewed-on: https://chromium-review.googlesource.com/997740
Commit-Queue: Henrik Grunell <grunell@chromium.org>
Reviewed-by: Jesse Doherty <jwd@chromium.org>
Reviewed-by: Max Morin <maxmorin@chromium.org>
Cr-Commit-Position: refs/heads/master@{#549492}

media/audio/win/audio_low_latency_input_win.cc

@@ -289,6 +289,8 @@ void WASAPIAudioInputStream::Close() {
   if (converter_)
     converter_->RemoveInput(this);
 
+  ReportAndResetGlitchStats();
+
   // Inform the audio manager that we have been closed. This will cause our
   // destruction.
   manager_->ReleaseInputStream(this);
@@ -466,14 +468,18 @@ void WASAPIAudioInputStream::PullCaptureDataAndPushToSink() {
     // Retrieve the amount of data in the capture endpoint buffer, replace it
     // with silence if required, create callbacks for each packet and store
     // non-delivered data for the next event.
-    // TODO(grunell): Should we handle
-    // |flags & AUDCLNT_BUFFERFLAGS_DATA_DISCONTINUITY|?
     HRESULT hr =
         audio_capture_client_->GetBuffer(&data_ptr, &num_frames_to_read, &flags,
                                          &device_position, &capture_time_100ns);
     if (hr == AUDCLNT_S_BUFFER_EMPTY)
       break;
 
+    ReportDelayStatsAndUpdateGlitchCount(
+        num_frames_to_read, flags & AUDCLNT_BUFFERFLAGS_DATA_DISCONTINUITY,
+        device_position,
+        base::TimeTicks() +
+            base::TimeDelta::FromMicroseconds(capture_time_100ns / 10.0));
+
     // TODO(grunell): Should we handle different errors explicitly? Perhaps exit
     // by setting |error = true|. What are the assumptions here that makes us
     // rely on the next WaitForMultipleObjects? Do we expect the next wait to be
@@ -957,4 +963,87 @@ double WASAPIAudioInputStream::ProvideInput(AudioBus* audio_bus,
   return 1.0;
 }
 
+void WASAPIAudioInputStream::ReportDelayStatsAndUpdateGlitchCount(
+    UINT32 frames_in_buffer,
+    bool discontinuity_flagged,
+    UINT64 device_position,
+    base::TimeTicks capture_time) {
+  // Report delay. Don't report if no valid capture time.
+  // Unreasonably large delays are clamped at 1 second. Some devices sometimes
+  // have capture timestamps way off.
+  if (capture_time > base::TimeTicks()) {
+    base::TimeDelta delay = base::TimeTicks::Now() - capture_time;
+    UMA_HISTOGRAM_CUSTOM_TIMES("Media.Audio.Capture.DeviceLatency", delay,
+                               base::TimeDelta::FromMilliseconds(1),
+                               base::TimeDelta::FromSeconds(1), 50);
+  }
+
+  // Detect glitch. Detect and count separately based on expected device
+  // position and the discontinuity flag since they have showed to not always
+  // be consistent with each other.
+  if (expected_next_device_position_ != 0) {
+    if (device_position > expected_next_device_position_) {
+      ++total_glitches_;
+      auto lost_frames = device_position - expected_next_device_position_;
+      total_lost_frames_ += lost_frames;
+      if (lost_frames > largest_glitch_frames_)
+        largest_glitch_frames_ = lost_frames;
+    } else if (device_position < expected_next_device_position_) {
+      ++total_device_position_less_than_expected_;
+    }
+    if (discontinuity_flagged)
+      ++total_discontinuities_;
+    if (device_position > expected_next_device_position_ &&
+        discontinuity_flagged) {
+      ++total_concurrent_glitch_and_discontinuities_;
+    }
+  }
+
+  expected_next_device_position_ = device_position + frames_in_buffer;
+}
+
+void WASAPIAudioInputStream::ReportAndResetGlitchStats() {
+  UMA_HISTOGRAM_COUNTS("Media.Audio.Capture.Glitches", total_glitches_);
+  UMA_HISTOGRAM_COUNTS("Media.Audio.Capture.Win.DevicePositionLessThanExpected",
+                       total_device_position_less_than_expected_);
+  UMA_HISTOGRAM_COUNTS("Media.Audio.Capture.Win.Discontinuities",
+                       total_discontinuities_);
+  UMA_HISTOGRAM_COUNTS(
+      "Media.Audio.Capture.Win.ConcurrentGlitchAndDiscontinuities",
+      total_concurrent_glitch_and_discontinuities_);
+
+  double lost_frames_ms =
+      (total_lost_frames_ * 1000) / input_format_.nSamplesPerSec;
+  std::string log_message = base::StringPrintf(
+      "WASAPIAIS: Total glitches=%d. Total frames lost=%llu (%.0lf ms). Total "
+      "discontinuities=%d. Total concurrent glitch and discont=%d. Total low "
+      "device "
+      "positions=%d.",
+      total_glitches_, total_lost_frames_, lost_frames_ms,
+      total_discontinuities_, total_concurrent_glitch_and_discontinuities_,
+      total_device_position_less_than_expected_);
+  log_callback_.Run(log_message);
+
+  if (total_glitches_ != 0) {
+    UMA_HISTOGRAM_LONG_TIMES("Media.Audio.Capture.LostFramesInMs",
+                             base::TimeDelta::FromMilliseconds(lost_frames_ms));
+    int64_t largest_glitch_ms =
+        (largest_glitch_frames_ * 1000) / input_format_.nSamplesPerSec;
+    UMA_HISTOGRAM_CUSTOM_TIMES(
+        "Media.Audio.Capture.LargestGlitchMs",
+        base::TimeDelta::FromMilliseconds(largest_glitch_ms),
+        base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromMinutes(1),
+        50);
+    DLOG(WARNING) << log_message;
+  }
+
+  expected_next_device_position_ = 0;
+  total_glitches_ = 0;
+  total_device_position_less_than_expected_ = 0;
+  total_discontinuities_ = 0;
+  total_concurrent_glitch_and_discontinuities_ = 0;
+  total_lost_frames_ = 0;
+  largest_glitch_frames_ = 0;
+}
+
 }  // namespace media

media/audio/win/audio_low_latency_input_win.h

@@ -144,6 +144,17 @@ class MEDIA_EXPORT WASAPIAudioInputStream
   // AudioConverter::InputCallback implementation.
   double ProvideInput(AudioBus* audio_bus, uint32_t frames_delayed) override;
 
+  // Reports delay stats based on |capture_time|. Detects and counts glitches
+  // based on |frames_in_buffer|, |discontinuity_flagged|, and
+  // |device_position|.
+  void ReportDelayStatsAndUpdateGlitchCount(UINT32 frames_in_buffer,
+                                            bool discontinuity_flagged,
+                                            UINT64 device_position,
+                                            base::TimeTicks capture_time);
+
+  // Reports glitch stats and resets associated variables.
+  void ReportAndResetGlitchStats();
+
   // Used to track down where we fail during initialization which at the
   // moment seems to be happening frequently and we're not sure why.
   // The reason might be expected (e.g. trying to open "default" on a machine
@@ -269,6 +280,15 @@ class MEDIA_EXPORT WASAPIAudioInputStream
   // Callback to send log messages.
   AudioManager::LogCallback log_callback_;
 
+  // For detecting and reporting glitches.
+  UINT64 expected_next_device_position_ = 0;
+  int total_glitches_ = 0;
+  int total_device_position_less_than_expected_ = 0;
+  int total_discontinuities_ = 0;
+  int total_concurrent_glitch_and_discontinuities_ = 0;
+  UINT64 total_lost_frames_ = 0;
+  UINT64 largest_glitch_frames_ = 0;
+
   SEQUENCE_CHECKER(sequence_checker_);
 
   DISALLOW_COPY_AND_ASSIGN(WASAPIAudioInputStream);

tools/metrics/histograms/histograms.xml

@@ -34716,6 +34716,16 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   </summary>
 </histogram>
 
+<histogram name="Media.Audio.Capture.DeviceLatency" units="ms">
+  <owner>grunell@chromium.org</owner>
+  <summary>
+    The audio input device latency. The time from when a frame was captured
+    until it reaches Chrome's platform audio implementation. Sampled for every
+    buffer received from the device, and reports the latency for the first frame
+    in the buffer.
+  </summary>
+</histogram>
+
 <histogram name="Media.Audio.Capture.FramesProvided" units="frames">
   <owner>grunell@chromium.org</owner>
   <summary>
@@ -34804,6 +34814,40 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   </summary>
 </histogram>
 
+<histogram name="Media.Audio.Capture.Win.ConcurrentGlitchAndDiscontinuities"
+    units="occurences">
+  <owner>grunell@chromium.org</owner>
+  <summary>
+    The number of times a glitch was detected by detecting skipped frames (as
+    with Media.Audio.Capture.Glitches) and disconituity was flagged by the OS at
+    the same time (as with Media.Audio.Capture.Win.Discontinuities). Sometimes
+    these indications are not consistent with each other so this metric helps
+    understanding how often they aren't. This value is logged when an audio
+    input stream is closed.
+  </summary>
+</histogram>
+
+<histogram name="Media.Audio.Capture.Win.DevicePositionLessThanExpected"
+    units="occurences">
+  <owner>grunell@chromium.org</owner>
+  <summary>
+    The number of times the device position was less than expected during the
+    lifetime of an audio stream. This value is logged when an audio input stream
+    is closed.
+  </summary>
+</histogram>
+
+<histogram name="Media.Audio.Capture.Win.Discontinuities"
+    units="discontinuities">
+  <owner>grunell@chromium.org</owner>
+  <summary>
+    The number of glitches that were detected at the OS level on Windows while
+    an audio stream was active, as reported by the OS via the discontinuity flag
+    (see IAudioCaptureClient::GetBuffer). This value is logged when an audio
+    input stream is closed.
+  </summary>
+</histogram>
+
 <histogram name="Media.Audio.Capture.Win.InitError" enum="Hresult">
   <owner>tommi@chromium.org</owner>
   <summary>