Audio input traces for Mac (browser-side)

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 <mach/mach.h>
 #include <string>
 
 #include "base/bind.h"
 #include "base/logging.h"
 #include "base/mac/mac_logging.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/metrics/sparse_histogram.h"
 #include "base/strings/stringprintf.h"
 #include "base/sys_info.h"
 #include "base/time/time.h"
+#include "base/trace_event/trace_event.h"
 #include "media/audio/mac/audio_manager_mac.h"
 #include "media/base/audio_bus.h"
 #include "media/base/data_buffer.h"
 
 namespace media {
 
 // Number of blocks of buffers used in the |fifo_|.
 const int kNumberOfBlocksBufferInFifo = 2;
 
 // Max length of sequence of TooManyFramesToProcessError errors.
@@ skipping 795 matching lines @@
   // is received from the input device via the output scope of the audio unit.
   return self->OnDataIsAvailable(flags, time_stamp, bus_number,
                                  number_of_frames);
 }
 
 OSStatus AUAudioInputStream::OnDataIsAvailable(
     AudioUnitRenderActionFlags* flags,
     const AudioTimeStamp* time_stamp,
     UInt32 bus_number,
     UInt32 number_of_frames) {
+  TRACE_EVENT0("audio", "AUAudioInputStream::OnDataIsAvailable");
   // Update |last_callback_time_| on the main browser thread. Its value is used
   // by CheckIfInputStreamIsAlive() to detect if the stream is dead or alive.
   manager_->GetTaskRunner()->PostTask(
       FROM_HERE,
       base::Bind(&AUAudioInputStream::UpdateDataCallbackTimeOnMainThread,
                  weak_factory_.GetWeakPtr(), base::TimeTicks::Now()));
 
   // Indicate that input callbacks have started on the internal AUHAL IO
   // thread. The |input_callback_is_active_| member is read from the creating
   // thread when a timer fires once and set to false in Stop() on the same
@@ skipping 28 matching lines @@
     }
 
     // Update the |mDataByteSize| to match |number_of_frames|.
     audio_buffer->mDataByteSize = new_size;
   }
 
   // Obtain the recorded audio samples by initiating a rendering cycle.
   // Since it happens on the input bus, the |&audio_buffer_list_| parameter is
   // a reference to the preallocated audio buffer list that the audio unit
   // renders into.
+  TRACE_EVENT_BEGIN0("audio", "AudioUnitRender");
   OSStatus result = AudioUnitRender(audio_unit_, flags, time_stamp, bus_number,
                                     number_of_frames, &audio_buffer_list_);
+  TRACE_EVENT_END0("audio", "AudioUnitRender");
   if (result == noErr) {
     audio_unit_render_has_worked_ = true;
   }
   if (result) {
+    TRACE_EVENT_INSTANT0("audio", "AudioUnitRender error",
+                         TRACE_EVENT_SCOPE_THREAD);
     // Only upload UMA histograms for the case when AGC is enabled. The reason
     // is that we want to compare these stats with others in this class and
     // they are only stored for "AGC streams", e.g. WebRTC audio streams.
     const bool add_uma_histogram = GetAutomaticGainControl();
     if (add_uma_histogram) {
       UMA_HISTOGRAM_SPARSE_SLOWLY("Media.AudioInputCbErrorMac", result);
     }
     OSSTATUS_LOG(ERROR, result) << "AudioUnitRender() failed ";
     if (result == kAudioUnitErr_TooManyFramesToProcess ||
         result == kAudioUnitErr_CannotDoInCurrentContext) {
@@ skipping 38 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) {
+  TRACE_EVENT1("audio", "AUAudioInputStream::Provide", "number_of_frames",
+               number_of_frames);
   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_provided_ == 0)
     number_of_frames_provided_ = number_of_frames;
 
   // Update the capture latency.
@@ skipping 18 matching lines @@
   // when the Display Audio is used as capture source and the cable is first
   // remove and then inserted again.
   // See http://www.crbug.com/434681 for details.
   if (static_cast<int>(number_of_frames) > fifo_.GetUnfilledFrames()) {
     // Derive required increase in number of FIFO blocks. The increase is
     // typically one block.
     const int blocks =
         static_cast<int>((number_of_frames - fifo_.GetUnfilledFrames()) /
                          number_of_frames_) + 1;
     DLOG(WARNING) << "Increasing FIFO capacity by " << blocks << " blocks";
+    TRACE_EVENT_INSTANT1("audio", "Increasing FIFO capacity",
+                         TRACE_EVENT_SCOPE_THREAD, "increased by", blocks);
     fifo_.IncreaseCapacity(blocks);
   }
 
   // Copy captured (and interleaved) data into FIFO.
   fifo_.Push(audio_data, number_of_frames, format_.mBitsPerChannel / 8);
 
   // Consume and deliver the data when the FIFO has a block of available data.
   while (fifo_.available_blocks()) {
     const AudioBus* audio_bus = fifo_.Consume();
     DCHECK_EQ(audio_bus->frames(), static_cast<int>(number_of_frames_));
@@ skipping 678 matching lines @@
 
   number_of_frames_provided_ = 0;
   glitches_detected_ = 0;
   last_sample_time_ = 0;
   last_number_of_frames_ = 0;
   total_lost_frames_ = 0;
   largest_glitch_frames_ = 0;
 }
 
 }  // namespace media