Add UMA stats for OS input glitches on Mac.

media/audio/mac/audio_low_latency_input_mac.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "media/audio/mac/audio_low_latency_input_mac.h"
 #include <CoreServices/CoreServices.h>
 
 #include "base/logging.h"
 #include "base/mac/mac_logging.h"
 #include "base/metrics/histogram_macros.h"
@@ skipping 109 matching lines @@
 
 // See "Technical Note TN2091 - Device input using the HAL Output Audio Unit"
 // http://developer.apple.com/library/mac/#technotes/tn2091/_index.html
 // for more details and background regarding this implementation.
 
 AUAudioInputStream::AUAudioInputStream(AudioManagerMac* manager,
                                        const AudioParameters& input_params,
                                        AudioDeviceID audio_device_id)
     : manager_(manager),
       number_of_frames_(input_params.frames_per_buffer()),
+      number_of_frames_requested_(0),
       io_buffer_frame_size_(0),
       sink_(nullptr),
       audio_unit_(0),
       input_device_id_(audio_device_id),
       hardware_latency_frames_(0),
       number_of_channels_in_frame_(0),
       fifo_(input_params.channels(),
             number_of_frames_,
             kNumberOfBlocksBufferInFifo),
       input_callback_is_active_(false),
       start_was_deferred_(false),
       buffer_size_was_changed_(false),
       audio_unit_render_has_worked_(false),
-      device_listener_is_active_(false) {
+      device_listener_is_active_(false),
+      last_sample_time_(0.0),
+      last_number_of_frames_(0),
+      total_lost_frames_(0),
+      largest_glitch_frames_(0),
+      glitches_detected_(0) {
   DCHECK(manager_);
 
   // Set up the desired (output) format specified by the client.
   format_.mSampleRate = input_params.sample_rate();
   format_.mFormatID = kAudioFormatLinearPCM;
   format_.mFormatFlags = kLinearPCMFormatFlagIsPacked |
                          kLinearPCMFormatFlagIsSignedInteger;
   DCHECK(FormatIsInterleaved(format_.mFormatFlags));
   format_.mBitsPerChannel = input_params.bits_per_sample();
   format_.mChannelsPerFrame = input_params.channels();
@@ skipping 22 matching lines @@
 
   AudioBuffer* audio_buffer = audio_buffer_list_.mBuffers;
   audio_buffer->mNumberChannels = input_params.channels();
   audio_buffer->mDataByteSize = data_byte_size;
   audio_buffer->mData = audio_data_buffer_.get();
 }
 
 AUAudioInputStream::~AUAudioInputStream() {
   DVLOG(1) << "~dtor";
   DCHECK(!device_listener_is_active_);
+  ReportAndResetStats();
 }
 
 // Obtain and open the AUHAL AudioOutputUnit for recording.
 bool AUAudioInputStream::Open() {
   DCHECK(thread_checker_.CalledOnValidThread());
   DVLOG(1) << "Open";
   DCHECK(!audio_unit_);
 
   // Verify that we have a valid device. Send appropriate error code to
   // HandleError() to ensure that the error type is added to UMA stats.
@@ skipping 260 matching lines @@
   // seems to set this state synchronously, hence it should always report false
   // after a successful call.
   DCHECK(!IsRunning()) << "Audio unit is stopped but still running";
 
   // Reset the audio unit’s render state. This function clears memory.
   // It does not allocate or free memory resources.
   result = AudioUnitReset(audio_unit_, kAudioUnitScope_Global, 0);
   DCHECK_EQ(result, noErr);
 
   SetInputCallbackIsActive(false);
+  ReportAndResetStats();
   sink_ = nullptr;
   fifo_.Clear();
   io_buffer_frame_size_ = 0;
   OSSTATUS_DLOG_IF(ERROR, result != noErr, result)
       << "Failed to stop acquiring data";
 }
 
 void AUAudioInputStream::Close() {
   DCHECK(thread_checker_.CalledOnValidThread());
   DVLOG(1) << "Close";
@@ skipping 277 matching lines @@
   // Update time of successful call to AudioUnitRender().
   last_success_time_ = base::TimeTicks::Now();
 
   // Deliver recorded data to the consumer as a callback.
   return Provide(number_of_frames, &audio_buffer_list_, time_stamp);
 }
 
 OSStatus AUAudioInputStream::Provide(UInt32 number_of_frames,
                                      AudioBufferList* io_data,
                                      const AudioTimeStamp* time_stamp) {
+  UpdateCaptureTimestamp(time_stamp);
+  last_number_of_frames_ = number_of_frames;
+
+  // TODO(grunell): We'll only care about the first buffer size change, any
+  // further changes will be ignored. This is in line with output side stats.
+  // It would be nice to have all changes reflected in UMA stats.
+  if (number_of_frames != number_of_frames_ && number_of_frames_requested_ == 0)
+    number_of_frames_requested_ = number_of_frames;
+
   // Update the capture latency.
   double capture_latency_frames = GetCaptureLatency(time_stamp);
 
   // The AGC volume level is updated once every second on a separate thread.
   // Note that, |volume| is also updated each time SetVolume() is called
   // through IPC by the render-side AGC.
   double normalized_volume = 0.0;
   GetAgcVolume(&normalized_volume);
 
   AudioBuffer& buffer = io_data->mBuffers[0];
@@ skipping 367 matching lines @@
         break;
     }
     DVLOG(1) << "property: " << device_property << " ("
              << FourCharFormatCodeToString(device_property) << ")"
              << " changed: " << change_count;
     LogDevicePropertyChange(startup_failed, uma_result);
   }
   device_property_changes_map_.clear();
 }
 
+void AUAudioInputStream::UpdateCaptureTimestamp(
+    const AudioTimeStamp* timestamp) {
+  if ((timestamp->mFlags & kAudioTimeStampSampleTimeValid) == 0)
+    return;
+
+  if (last_sample_time_) {
+    DCHECK_NE(0U, last_number_of_frames_);
+    UInt32 diff =
+        static_cast<UInt32>(timestamp->mSampleTime - last_sample_time_);
+    if (diff != last_number_of_frames_) {
+      DCHECK_GT(diff, last_number_of_frames_);
+      // We were given samples post what we expected. Update the glitch count
+      // etc. and keep a record of the largest glitch.
+      auto lost_frames = diff - last_number_of_frames_;
+      total_lost_frames_ += lost_frames;
+      if (lost_frames > largest_glitch_frames_)
+        largest_glitch_frames_ = lost_frames;
+      ++glitches_detected_;
+    }
+  }
+
+  // Store the last sample time for use next time we get called back.
+  last_sample_time_ = timestamp->mSampleTime;
+}
+
+void AUAudioInputStream::ReportAndResetStats() {
+  if (last_sample_time_ == 0)
+    return;  // No stats gathered to report.
+
+  // A value of 0 indicates that we got the buffer size we asked for.
+  UMA_HISTOGRAM_COUNTS("Media.Audio.Capture.FramesRequested",
+                       number_of_frames_requested_);

[Mark P, 2016/02/26 17:10:55]

Is the standard COUNTS histogram the right range?  Up to a million frames
requested.  That sounds implausible to me.  Maybe one of the other COUNTS
histograms has a better size.

[tommi (sloooow) - chröme, 2016/02/26 17:27:43]

These are audio "frames".  There will be tens of thousands of these per second,
so million is actually reasonable (it's about 20 seconds if we get 48000 frames
per second).

[Mark P, 2016/02/26 18:37:19]

Ah, thanks for the explanation.  This seems alright then.

[Henrik Grunell, 2016/02/29 17:48:48]

Actually, this is number of frames requested per callback, i.e. typically below
1000. Changed to COUNTS_10000.

+  // Even if there aren't any glitches, we want to record it to get a feel for
+  // how often we get no glitches vs the alternative.
+  UMA_HISTOGRAM_CUSTOM_COUNTS("Media.Audio.Capture.Glitches",
+                              glitches_detected_, 0, 999999, 100);

[Mark P, 2016/02/26 17:10:55]

With these parameters, the histogram looks basically identical to the standard
UMA_HISTOGRAM_COUNTS histogram.  Sure, the maximum bucket is 999,999 instead of
1,000,000 but I know you can't care about that.  Please use the standard counts
histogram unless you have a reason not to.

[tommi (sloooow) - chröme, 2016/02/26 17:27:43]

This doubles the bucket count though - or am I missing something?

[Mark P, 2016/02/26 18:37:19]

Ah, I see, you're using twice as many buckets as the default macro.  Do you have
a reason you need more than the typical amount of precision?

[Henrik Grunell, 2016/02/29 17:48:48]

Tommi, do you have the rationale for this? (Since this is based on the output
side stats you wrote.) I'd say 50 should be enough. Changed it to 50 meanwhile.

+
+  if (glitches_detected_ != 0) {
+    auto lost_frames_ms = (total_lost_frames_ * 1000) / format_.mSampleRate;
+    UMA_HISTOGRAM_COUNTS("Media.Audio.Capture.LostFramesInMs", lost_frames_ms);

[Mark P, 2016/02/26 17:10:55]

Either use one of the standard UMA times histograms or explain in a comment here
why you're instead using a COUNTS histogram.

[Henrik Grunell, 2016/02/29 17:48:48]

Changed to LONG_TIMES and below to CUSTOM_TIMES with 1 minute as max.

+    auto largest_glitch_ms =
+        (largest_glitch_frames_ * 1000) / format_.mSampleRate;
+    UMA_HISTOGRAM_COUNTS("Media.Audio.Capture.LargestGlitchMs",
+                         largest_glitch_ms);
+    DLOG(WARNING) << "Total glitches=" << glitches_detected_
+                  << ". Total frames lost=" << total_lost_frames_ << " ("
+                  << lost_frames_ms;
+  }
+
+  number_of_frames_requested_ = 0;
+  glitches_detected_ = 0;
+  last_sample_time_ = 0;
+  last_number_of_frames_ = 0;
+  total_lost_frames_ = 0;
+  largest_glitch_frames_ = 0;
+}
+
 }  // namespace media