Extends native logging for OutputController and OutputStream.

Adds support for:
- Tracking stream creation sequence using unique ID.
- Improves native logging related to usage of fake output streams.
- "Stream is alive" marker.
- Duration of stream.
- Injects logger into PulseAudioOutputStream.
- Improves native logs in AudioManagerBase.

Example result:

https://paste.googleplex.com/6677685310849024

Bug: 1017219
Change-Id: I9ae2d5a87a81e19de15faddfb1cd66250805eaf1
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2019243
Commit-Queue: Henrik Andreasson <henrika@chromium.org>
Reviewed-by: Olga Sharonova <olka@chromium.org>
Reviewed-by: Dale Curtis <dalecurtis@chromium.org>
Reviewed-by: Guido Urdaneta <guidou@chromium.org>
Cr-Commit-Position: refs/heads/master@{#741178}

content/browser/renderer_host/media/media_stream_manager.cc

@@ -675,13 +675,13 @@ class MediaStreamManager::DeviceRequest {
 
 // static
 void MediaStreamManager::SendMessageToNativeLog(const std::string& message) {
-  DVLOG(1) << message;
   if (!BrowserThread::CurrentlyOn(BrowserThread::IO)) {
     base::PostTask(
         FROM_HERE, {BrowserThread::IO},
         base::BindOnce(&MediaStreamManager::SendMessageToNativeLog, message));
     return;
   }
+  DVLOG(1) << message;
 
   MediaStreamManager* msm = g_media_stream_manager_tls_ptr.Pointer()->Get();
   if (!msm) {

media/audio/audio_manager_base.cc

@@ -63,6 +63,18 @@ enum StreamFormat {
   STREAM_FORMAT_MAX = 4,
 };
 
+PRINTF_FORMAT(2, 3)
+void SendLogMessage(const AudioManagerBase::LogCallback& callback,
+                    const char* format,
+                    ...) {
+  if (callback.is_null())
+    return;
+  va_list args;
+  va_start(args, format);
+  callback.Run("AMB::" + base::StringPrintV(format, args));
+  va_end(args);
+}
+
 }  // namespace
 
 struct AudioManagerBase::DispatcherParams {
@@ -188,6 +200,9 @@ AudioOutputStream* AudioManagerBase::MakeAudioOutputStream(
     return nullptr;
   }
 
+  SendLogMessage(log_callback, "%s({device_id=%s}, {params=[%s]})", __func__,
+                 device_id.c_str(), params.AsHumanReadableString().c_str());
+
   // Limit the number of audio streams opened. This is to prevent using
   // excessive resources for a large number of audio streams. More
   // importantly it prevents instability on certain systems.
@@ -224,6 +239,8 @@ AudioOutputStream* AudioManagerBase::MakeAudioOutputStream(
 
   if (stream) {
     ++num_output_streams_;
+    SendLogMessage(log_callback, "%s => (number of streams=%d)", __func__,
+                   output_stream_count());
   }
 
   return stream;
@@ -247,6 +264,9 @@ AudioInputStream* AudioManagerBase::MakeAudioInputStream(
     return nullptr;
   }
 
+  SendLogMessage(log_callback, "%s({device_id=%s}, {params=[%s]})", __func__,
+                 device_id.c_str(), params.AsHumanReadableString().c_str());
+
   if (!params.IsValid() || (params.channels() > kMaxInputChannels) ||
       device_id.empty()) {
     DLOG(ERROR) << "Audio parameters are invalid for device " << device_id;
@@ -283,9 +303,8 @@ AudioInputStream* AudioManagerBase::MakeAudioInputStream(
   if (stream) {
     input_streams_.insert(stream);
     if (!log_callback.is_null()) {
-      log_callback.Run(base::StringPrintf(
-          "AMB::MakeAudioInputStream => (number of streams=%d)",
-          input_stream_count()));
+      SendLogMessage(log_callback, "%s => (number of streams=%d)", __func__,
+                     input_stream_count());
     }
 
     if (!params.IsBitstreamFormat() && debug_recording_manager_) {

media/audio/audio_output_proxy.h

@@ -16,7 +16,7 @@ namespace media {
 
 class AudioOutputDispatcher;
 
-// AudioOutputProxy is an audio otput stream that uses resources more
+// AudioOutputProxy is an audio output stream that uses resources more
 // efficiently than a regular audio output stream: it opens audio
 // device only when sound is playing, i.e. between Start() and Stop()
 // (there is still one physical stream per each audio output proxy in

media/audio/pulse/audio_manager_pulse.cc

@@ -135,7 +135,8 @@ AudioOutputStream* AudioManagerPulse::MakeLinearOutputStream(
     const AudioParameters& params,
     const LogCallback& log_callback) {
   DCHECK_EQ(AudioParameters::AUDIO_PCM_LINEAR, params.format());
-  return MakeOutputStream(params, AudioDeviceDescription::kDefaultDeviceId);
+  return MakeOutputStream(params, AudioDeviceDescription::kDefaultDeviceId,
+                          log_callback);
 }
 
 AudioOutputStream* AudioManagerPulse::MakeLowLatencyOutputStream(
@@ -143,9 +144,10 @@ AudioOutputStream* AudioManagerPulse::MakeLowLatencyOutputStream(
     const std::string& device_id,
     const LogCallback& log_callback) {
   DCHECK_EQ(AudioParameters::AUDIO_PCM_LOW_LATENCY, params.format());
-  return MakeOutputStream(params, device_id.empty()
-                                      ? AudioDeviceDescription::kDefaultDeviceId
-                                      : device_id);
+  return MakeOutputStream(
+      params,
+      device_id.empty() ? AudioDeviceDescription::kDefaultDeviceId : device_id,
+      log_callback);
 }
 
 AudioInputStream* AudioManagerPulse::MakeLinearInputStream(
@@ -238,9 +240,10 @@ AudioParameters AudioManagerPulse::GetPreferredOutputStreamParameters(
 
 AudioOutputStream* AudioManagerPulse::MakeOutputStream(
     const AudioParameters& params,
-    const std::string& device_id) {
+    const std::string& device_id,
+    const LogCallback& log_callback) {
   DCHECK(!device_id.empty());
-  return new PulseAudioOutputStream(params, device_id, this);
+  return new PulseAudioOutputStream(params, device_id, this, log_callback);
 }
 
 AudioInputStream* AudioManagerPulse::MakeInputStream(

media/audio/pulse/audio_manager_pulse.h

@@ -89,7 +89,8 @@ class MEDIA_EXPORT AudioManagerPulse : public AudioManagerBase {
 
   // Called by MakeLinearOutputStream and MakeLowLatencyOutputStream.
   AudioOutputStream* MakeOutputStream(const AudioParameters& params,
-                                      const std::string& device_id);
+                                      const std::string& device_id,
+                                      const LogCallback& log_callback);
 
   // Called by MakeLinearInputStream and MakeLowLatencyInputStream.
   AudioInputStream* MakeInputStream(const AudioParameters& params,

media/audio/pulse/pulse_output.cc

@@ -7,7 +7,9 @@
 #include <pulse/pulseaudio.h>
 #include <stdint.h>
 
+#include "base/compiler_specific.h"
 #include "base/single_thread_task_runner.h"
+#include "base/strings/stringprintf.h"
 #include "base/time/time.h"
 #include "media/audio/audio_device_description.h"
 #include "media/audio/audio_manager_base.h"
@@ -16,6 +18,22 @@
 
 namespace media {
 
+namespace {
+
+PRINTF_FORMAT(2, 3)
+void SendLogMessage(const AudioManagerBase::LogCallback& callback,
+                    const char* format,
+                    ...) {
+  if (callback.is_null())
+    return;
+  va_list args;
+  va_start(args, format);
+  callback.Run("PAOS::" + base::StringPrintV(format, args));
+  va_end(args);
+}
+
+}  // namespace
+
 using pulse::AutoPulseLock;
 using pulse::WaitForOperationCompletion;
 
@@ -41,22 +59,29 @@ void PulseAudioOutputStream::StreamRequestCallback(pa_stream* s, size_t len,
   static_cast<PulseAudioOutputStream*>(p_this)->FulfillWriteRequest(len);
 }
 
-PulseAudioOutputStream::PulseAudioOutputStream(const AudioParameters& params,
+PulseAudioOutputStream::PulseAudioOutputStream(
+    const AudioParameters& params,
     const std::string& device_id,
-                                               AudioManagerBase* manager)
+    AudioManagerBase* manager,
+    const AudioManager::LogCallback log_callback)
     : params_(AudioParameters(params.format(),
                               params.channel_layout(),
                               params.sample_rate(),
                               params.frames_per_buffer())),
       device_id_(device_id),
       manager_(manager),
-      pa_context_(NULL),
-      pa_mainloop_(NULL),
-      pa_stream_(NULL),
+      log_callback_(std::move(log_callback)),
+      pa_context_(nullptr),
+      pa_mainloop_(nullptr),
+      pa_stream_(nullptr),
       volume_(1.0f),
-      source_callback_(NULL),
+      source_callback_(nullptr),
       buffer_size_(params_.GetBytesPerBuffer(kSampleFormatF32)) {
   CHECK(params_.IsValid());
+  SendLogMessage(
+      log_callback_,
+      "PulseAudioOutputStream({device_id=%s}, {params=[%s]} [this=%p])",
+      device_id.c_str(), params.AsHumanReadableString().c_str(), this);
   audio_bus_ = AudioBus::Create(params_);
 }
 
@@ -70,10 +95,15 @@ PulseAudioOutputStream::~PulseAudioOutputStream() {
 
 bool PulseAudioOutputStream::Open() {
   DCHECK(thread_checker_.CalledOnValidThread());
-  return pulse::CreateOutputStream(
+  SendLogMessage(log_callback_, "Open([this=%p])", this);
+  bool result = pulse::CreateOutputStream(
       &pa_mainloop_, &pa_context_, &pa_stream_, params_, device_id_,
       AudioManager::GetGlobalAppName(), &StreamNotifyCallback,
       &StreamRequestCallback, this);
+  if (!result) {
+    SendLogMessage(log_callback_, "Open => (ERROR: failed to open PA stream)");
+  }
+  return result;
 }
 
 void PulseAudioOutputStream::Reset() {
@@ -96,27 +126,28 @@ void PulseAudioOutputStream::Reset() {
 
       // Release PulseAudio structures.
       pa_stream_disconnect(pa_stream_);
-      pa_stream_set_write_callback(pa_stream_, NULL, NULL);
-      pa_stream_set_state_callback(pa_stream_, NULL, NULL);
+      pa_stream_set_write_callback(pa_stream_, nullptr, nullptr);
+      pa_stream_set_state_callback(pa_stream_, nullptr, nullptr);
       pa_stream_unref(pa_stream_);
-      pa_stream_ = NULL;
+      pa_stream_ = nullptr;
     }
 
     if (pa_context_) {
       pa_context_disconnect(pa_context_);
-      pa_context_set_state_callback(pa_context_, NULL, NULL);
+      pa_context_set_state_callback(pa_context_, nullptr, nullptr);
       pa_context_unref(pa_context_);
-      pa_context_ = NULL;
+      pa_context_ = nullptr;
     }
   }
 
   pa_threaded_mainloop_stop(pa_mainloop_);
   pa_threaded_mainloop_free(pa_mainloop_);
-  pa_mainloop_ = NULL;
+  pa_mainloop_ = nullptr;
 }
 
 void PulseAudioOutputStream::Close() {
   DCHECK(thread_checker_.CalledOnValidThread());
+  SendLogMessage(log_callback_, "Close([this=%p])", this);
 
   Reset();
 
@@ -138,7 +169,7 @@ void PulseAudioOutputStream::FulfillWriteRequest(size_t requested_bytes) {
 
     if (!source_callback_) {
       memset(pa_buffer, 0, pa_buffer_size);
-      pa_stream_write(pa_stream_, pa_buffer, pa_buffer_size, NULL, 0LL,
+      pa_stream_write(pa_stream_, pa_buffer, pa_buffer_size, nullptr, 0LL,
                       PA_SEEK_RELATIVE);
       bytes_remaining -= pa_buffer_size;
       continue;
@@ -172,7 +203,7 @@ void PulseAudioOutputStream::FulfillWriteRequest(size_t requested_bytes) {
       frame_offset_in_bus += frames_to_copy;
       unwritten_frames_in_bus -= frames_to_copy;
 
-      if (pa_stream_write(pa_stream_, pa_buffer, pa_buffer_size, NULL, 0LL,
+      if (pa_stream_write(pa_stream_, pa_buffer, pa_buffer_size, nullptr, 0LL,
                           PA_SEEK_RELATIVE) < 0) {
         source_callback_->OnError(AudioSourceCallback::ErrorType::kUnknown);
         return;
@@ -200,6 +231,7 @@ void PulseAudioOutputStream::Start(AudioSourceCallback* callback) {
   DCHECK(thread_checker_.CalledOnValidThread());
   CHECK(callback);
   CHECK(pa_stream_);
+  SendLogMessage(log_callback_, "Start([this=%p])", this);
 
   AutoPulseLock auto_lock(pa_mainloop_);
 
@@ -223,13 +255,14 @@ void PulseAudioOutputStream::Start(AudioSourceCallback* callback) {
 
 void PulseAudioOutputStream::Stop() {
   DCHECK(thread_checker_.CalledOnValidThread());
+  SendLogMessage(log_callback_, "Stop([this=%p])", this);
 
   // Cork (pause) the stream.  Waiting for the main loop lock will ensure
   // outstanding callbacks have completed.
   AutoPulseLock auto_lock(pa_mainloop_);
 
-  // Set |source_callback_| to NULL so all FulfillWriteRequest() calls which may
-  // occur while waiting on the flush and cork exit immediately.
+  // Set |source_callback_| to nullptr so all FulfillWriteRequest() calls which
+  // may occur while waiting on the flush and cork exit immediately.
   auto* callback = source_callback_;
   source_callback_ = nullptr;
 

media/audio/pulse/pulse_output.h

@@ -28,6 +28,7 @@
 #include "base/macros.h"
 #include "base/threading/thread_checker.h"
 #include "media/audio/audio_io.h"
+#include "media/audio/audio_manager.h"
 #include "media/base/audio_parameters.h"
 
 struct pa_context;
@@ -41,7 +42,8 @@ class PulseAudioOutputStream : public AudioOutputStream {
  public:
   PulseAudioOutputStream(const AudioParameters& params,
                          const std::string& device_id,
-                         AudioManagerBase* manager);
+                         AudioManagerBase* manager,
+                         const AudioManager::LogCallback log_callback);
 
   ~PulseAudioOutputStream() override;
 
@@ -79,6 +81,9 @@ class PulseAudioOutputStream : public AudioOutputStream {
   // Audio manager that created us.  Used to report that we've closed.
   AudioManagerBase* manager_;
 
+  // Callback to send log messages to registered clients.
+  AudioManager::LogCallback log_callback_;
+
   // PulseAudio API structs.
   pa_context* pa_context_;
   pa_threaded_mainloop* pa_mainloop_;

media/base/audio_parameters.cc

@@ -9,6 +9,22 @@
 
 namespace media {
 
+const char* FormatToString(AudioParameters::Format format) {
+  switch (format) {
+    case AudioParameters::AUDIO_PCM_LINEAR:
+      return "PCM_LINEAR";
+    case AudioParameters::AUDIO_PCM_LOW_LATENCY:
+      return "PCM_LOW_LATENCY";
+    case AudioParameters::AUDIO_BITSTREAM_AC3:
+      return "BITSTREAM_AC3";
+    case AudioParameters::AUDIO_BITSTREAM_EAC3:
+      return "BITSTREAM_EAC3";
+    case AudioParameters::AUDIO_FAKE:
+      return "FAKE";
+  }
+  return "INVALID";
+}
+
 base::CheckedNumeric<uint32_t> ComputeAudioInputBufferSizeChecked(
     const AudioParameters& parameters,
     uint32_t shared_memory_count) {
@@ -117,8 +133,9 @@ bool AudioParameters::IsValid() const {
 
 std::string AudioParameters::AsHumanReadableString() const {
   std::ostringstream s;
-  s << "format: " << format() << ", channel_layout: " << channel_layout()
-    << ", channels: " << channels() << ", sample_rate: " << sample_rate()
+  s << "format: " << FormatToString(format())
+    << ", channel_layout: " << channel_layout() << ", channels: " << channels()
+    << ", sample_rate: " << sample_rate()
     << ", frames_per_buffer: " << frames_per_buffer()
     << ", effects: " << effects()
     << ", mic_positions: " << PointsToString(mic_positions_);

services/audio/output_controller.h

@@ -13,6 +13,7 @@
 
 #include "base/atomic_ref_count.h"
 #include "base/callback.h"
+#include "base/compiler_specific.h"
 #include "base/containers/flat_set.h"
 #include "base/macros.h"
 #include "base/memory/weak_ptr.h"
@@ -103,6 +104,16 @@ class OutputController : public media::AudioOutputStream::AudioSourceCallback,
     virtual void Close() = 0;
   };
 
+  // Internal state of the source.
+  enum State {
+    kEmpty,
+    kCreated,
+    kPlaying,
+    kPaused,
+    kClosed,
+    kError,
+  };
+
   // |audio_manager| and |handler| must outlive OutputController.  The
   // |output_device_id| can be either empty (default device) or specify a
   // specific hardware device for audio output.
@@ -177,17 +188,9 @@ class OutputController : public media::AudioOutputStream::AudioSourceCallback,
   // audio_power_monitor.h for usage.  This may be called on any thread.
   std::pair<float, bool> ReadCurrentPowerAndClip();
 
- protected:
-  // Internal state of the source.
-  enum State {
-    kEmpty,
-    kCreated,
-    kPlaying,
-    kPaused,
-    kClosed,
-    kError,
-  };
+  base::UnguessableToken processing_id() const { return processing_id_; }
 
+ protected:
   // Time constant for AudioPowerMonitor.  See AudioPowerMonitor ctor comments
   // for semantics.  This value was arbitrarily chosen, but seems to work well.
   enum { kPowerMeasurementTimeConstantMillis = 10 };
@@ -206,7 +209,9 @@ class OutputController : public media::AudioOutputStream::AudioSourceCallback,
   // cycle.
   class ErrorStatisticsTracker {
    public:
-    ErrorStatisticsTracker();
+    // |handler| must outlive the ErrorStatisticsTracker. See comments for
+    // |OutputController::handler_| why it is safe to use a raw pointer here.
+    ErrorStatisticsTracker(EventHandler* handler);
 
     // Note: the destructor takes care of logging all of the stats.
     ~ErrorStatisticsTracker();
@@ -220,6 +225,10 @@ class OutputController : public media::AudioOutputStream::AudioSourceCallback,
    private:
     void WedgeCheck();
 
+    // Using a raw pointer is safe since the EventHandler object will outlive
+    // the ErrorStatisticsTracker object.
+    EventHandler* const handler_;
+
     const base::TimeTicks start_time_;
 
     bool error_during_callback_ = false;
@@ -247,6 +256,9 @@ class OutputController : public media::AudioOutputStream::AudioSourceCallback,
   // Helper method that stops, closes, and NULLs |*stream_|.
   void StopCloseAndClearStream();
 
+  // Helper method which delivers a log string to the event handler.
+  void SendLogMessage(const char* fmt, ...) PRINTF_FORMAT(2, 3);
+
   // Log the current average power level measured by power_monitor_.
   void LogAudioPowerLevel(const char* call_name);
 
@@ -256,6 +268,11 @@ class OutputController : public media::AudioOutputStream::AudioSourceCallback,
 
   media::AudioManager* const audio_manager_;
   const media::AudioParameters params_;
+
+  // This object (OC) is owned by an OutputStream (OS) object which is an
+  // EventHandler. |handler_| is set at construction by the OS (using this).
+  // It is safe to use a raw pointer here since the OS will always outlive
+  // the OC object.
   EventHandler* const handler_;
 
   // The task runner for the audio manager. All control methods should be called

services/audio/output_stream.cc

@@ -8,6 +8,7 @@
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
+#include "base/strings/stringprintf.h"
 #include "base/threading/sequenced_task_runner_handle.h"
 #include "base/trace_event/trace_event.h"
 
@@ -19,6 +20,16 @@ const float kSilenceThresholdDBFS = -72.24719896f;
 // "blip" sounds won't be detected.  http://crbug.com/339133#c4
 const int kPowerMeasurementsPerSecond = 15;
 
+std::string GetCtorLogString(const base::UnguessableToken& id,
+                             media::AudioManager* audio_manager,
+                             const std::string& device_id,
+                             const media::AudioParameters& params) {
+  return base::StringPrintf(
+      "Ctor({id=%s}, {audio_manager_name=%s}, {device_id=%s}, {params=[%s]})",
+      id.ToString().c_str(), audio_manager->GetName(), device_id.c_str(),
+      params.AsHumanReadableString().c_str());
+}
+
 OutputStream::OutputStream(
     CreatedCallback created_callback,
     DeleteCallback delete_callback,
@@ -61,6 +72,9 @@ OutputStream::OutputStream(
   TRACE_EVENT_NESTABLE_ASYNC_BEGIN2("audio", "OutputStream", this, "device id",
                                     output_device_id, "params",
                                     params.AsHumanReadableString());
+  SendLogMessage("%s", GetCtorLogString(processing_id, audio_manager,
+                                        output_device_id, params)
+                           .c_str());
 
   // |this| owns these objects, so unretained is safe.
   base::RepeatingClosure error_handler =
@@ -154,6 +168,8 @@ void OutputStream::CreateAudioPipe(CreatedCallback created_callback) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
   DCHECK(reader_.IsValid());
   TRACE_EVENT_NESTABLE_ASYNC_INSTANT0("audio", "CreateAudioPipe", this);
+  SendLogMessage("CreateAudioPipe({id=%s})",
+                 processing_id().ToString().c_str());
 
   base::UnsafeSharedMemoryRegion shared_memory_region =
       reader_.TakeSharedMemoryRegion();
@@ -216,6 +232,8 @@ void OutputStream::OnControllerPaused() {
 void OutputStream::OnControllerError() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
   TRACE_EVENT_NESTABLE_ASYNC_INSTANT0("audio", "OnControllerError", this);
+  SendLogMessage("OnControllerError({id=%s})",
+                 processing_id().ToString().c_str());
 
   // Stop checking the audio level to avoid using this object while it's being
   // torn down.
@@ -236,8 +254,11 @@ void OutputStream::OnControllerError() {
 
 void OutputStream::OnLog(base::StringPiece message) {
   // No sequence check: |log_| is thread-safe.
-  if (log_)
-    log_->OnLogMessage(message.as_string());
+  if (log_) {
+    log_->OnLogMessage(base::StringPrintf("%s [id=%s]",
+                                          message.as_string().c_str(),
+                                          processing_id().ToString().c_str()));
+  }
 }
 
 void OutputStream::OnError() {
@@ -259,6 +280,8 @@ void OutputStream::CallDeleter() {
   std::move(delete_callback_).Run(this);
 }
 
+// TODO(crbug.com/1017219): it might be useful to track these transitions with
+// logs as well but note that the method is called at a rather high rate.
 void OutputStream::PollAudioLevel() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
 
@@ -283,4 +306,13 @@ bool OutputStream::IsAudible() {
   return power_dbfs >= kSilenceThresholdDBFS;
 }
 
+void OutputStream::SendLogMessage(const char* format, ...) {
+  if (!log_)
+    return;
+  va_list args;
+  va_start(args, format);
+  log_->OnLogMessage("audio::OS::" + base::StringPrintV(format, args));
+  va_end(args);
+}
+
 }  // namespace audio

services/audio/output_stream.h

@@ -85,6 +85,16 @@ class OutputStream final : public media::mojom::AudioOutputStream,
   void PollAudioLevel();
   bool IsAudible();
 
+  // Internal helper method for sending logs related  to this class to clients
+  // registered to receive these logs. Prepends each log with "audio::OS" to
+  // point out its origin. Compare with OutputController::EventHandler::OnLog()
+  // which only will be called by the |controller_| object. These logs are
+  // prepended with "AOC::" where AOC corresponds to AudioOutputController.
+  void SendLogMessage(const char* format, ...) PRINTF_FORMAT(2, 3);
+  base::UnguessableToken processing_id() const {
+    return controller_.processing_id();
+  }
+
   SEQUENCE_CHECKER(owning_sequence_);
 
   base::CancelableSyncSocket foreign_socket_;