[Chromecast] Add AUDIO_LOG to avoid blocking the mixer thread

 * Avoid allocating memory during logging.
 * Post logs to a lower-priority thread for actual output.

Bug: internal b/162244426
Change-Id: Iae080bcfebc96a151fed6f108cbfb12ff70a44ae
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2324819Reviewed-by: Yuchen Liu <yucliu@chromium.org>
Commit-Queue: Kenneth MacKay <kmackay@chromium.org>
Cr-Commit-Position: refs/heads/master@{#794783}

chromecast/media/audio/BUILD.gn

@@ -13,6 +13,15 @@ declare_args() {
   default_output_buffer_size_in_frames = 2048
 }
 
+cast_source_set("audio_log") {
+  sources = [
+    "audio_log.cc",
+    "audio_log.h",
+  ]
+
+  deps = [ "//base" ]
+}
+
 cast_source_set("audio_io_thread") {
   sources = [
     "audio_io_thread.cc",

chromecast/media/audio/audio_log.cc

+// Copyright 2020 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 "chromecast/media/audio/audio_log.h"
+
+#include <algorithm>
+
+#include "base/bind.h"
+#include "base/callback.h"
+#include "base/location.h"
+#include "base/memory/scoped_refptr.h"
+#include "base/no_destructor.h"
+#include "base/sequenced_task_runner.h"
+#include "base/synchronization/lock.h"
+#include "base/thread_annotations.h"
+#include "base/threading/sequenced_task_runner_handle.h"
+
+namespace logging {
+
+namespace {
+constexpr int kBufferSize = 256;
+constexpr int kMaxBuffers = 16;
+}  // namespace
+
+class AudioLogMessage::StreamBuf : public std::streambuf {
+ public:
+  StreamBuf() = default;
+
+  StreamBuf(const StreamBuf&) = delete;
+  StreamBuf& operator=(const StreamBuf&) = delete;
+
+  void Initialize(const char* file, int line, LogSeverity severity) {
+    file_ = file;
+    line_ = line;
+    severity_ = severity;
+    setp(buffer_, buffer_ + kBufferSize);
+  }
+
+  void Log() {
+    ::logging::LogMessage message(file_, line_, severity_);
+    int size = pptr() - pbase();
+    message.stream().write(buffer_, size);
+  }
+
+ private:
+  const char* file_ = nullptr;
+  int line_;
+  LogSeverity severity_;
+  char buffer_[kBufferSize];
+};
+
+namespace {
+
+class BufferManager {
+ public:
+  static BufferManager* Get();
+
+  void Setup() {
+    base::AutoLock lock(lock_);
+    if (ready_) {
+      return;
+    }
+
+    task_runner_ = base::SequencedTaskRunnerHandle::Get();
+    dispose_callback_ = base::BindRepeating(
+        &BufferManager::HandleDisposedBuffers, base::Unretained(this));
+
+    for (int i = 0; i < kMaxBuffers; ++i) {
+      free_buffers_[i] = &buffers_[i];
+    }
+    num_free_buffers_ = kMaxBuffers;
+    ready_ = true;
+  }
+
+  AudioLogMessage::StreamBuf* GetBuffer(const char* file,
+                                        int line,
+                                        LogSeverity severity) {
+    AudioLogMessage::StreamBuf* buffer;
+    {
+      base::AutoLock lock(lock_);
+      if (num_free_buffers_ == 0) {
+        ++num_missing_buffers_;
+        return nullptr;
+      }
+
+      --num_free_buffers_;
+      buffer = free_buffers_[num_free_buffers_];
+    }
+    buffer->Initialize(file, line, severity);
+    return buffer;
+  }
+
+  void Dispose(AudioLogMessage::StreamBuf* buffer) {
+    if (!buffer) {
+      return;
+    }
+
+    {
+      base::AutoLock lock(lock_);
+      DCHECK_LT(num_disposed_buffers_, kMaxBuffers);
+      disposed_buffers_[num_disposed_buffers_] = buffer;
+      ++num_disposed_buffers_;
+    }
+    DCHECK(task_runner_);
+    task_runner_->PostTask(FROM_HERE, dispose_callback_);
+  }
+
+ private:
+  void HandleDisposedBuffers() {
+    AudioLogMessage::StreamBuf* buffers[kMaxBuffers];
+    int num_buffers;
+    int num_missing;
+    {
+      base::AutoLock lock(lock_);
+      std::copy_n(disposed_buffers_, num_disposed_buffers_, buffers);
+      num_buffers = num_disposed_buffers_;
+      num_disposed_buffers_ = 0;
+
+      num_missing = num_missing_buffers_;
+      num_missing_buffers_ = 0;
+    }
+
+    for (int i = 0; i < num_buffers; ++i) {
+      buffers[i]->Log();
+      {
+        base::AutoLock lock(lock_);
+        free_buffers_[num_free_buffers_] = buffers[i];
+        ++num_free_buffers_;
+      }
+    }
+
+    LOG_IF(ERROR, num_missing > 0)
+        << num_missing << " log messages lost due to lack of buffers";
+  }
+
+  AudioLogMessage::StreamBuf buffers_[kMaxBuffers];
+
+  base::Lock lock_;
+  bool ready_ GUARDED_BY(lock_) = false;
+  AudioLogMessage::StreamBuf* free_buffers_[kMaxBuffers] GUARDED_BY(lock_);
+  int num_free_buffers_ GUARDED_BY(lock_) = 0;
+
+  AudioLogMessage::StreamBuf* disposed_buffers_[kMaxBuffers] GUARDED_BY(lock_);
+  int num_disposed_buffers_ GUARDED_BY(lock_) = 0;
+
+  int num_missing_buffers_ GUARDED_BY(lock_) = 0;
+
+  scoped_refptr<base::SequencedTaskRunner> task_runner_;
+  base::RepeatingClosure dispose_callback_;
+};
+
+// static
+BufferManager* BufferManager::Get() {
+  static base::NoDestructor<BufferManager> g_buffer_manager;
+  return g_buffer_manager.get();
+}
+
+}  // namespace
+
+AudioLogMessage::AudioLogMessage(const char* file,
+                                 int line,
+                                 LogSeverity severity)
+    : buffer_(BufferManager::Get()->GetBuffer(file, line, severity)),
+      stream_(buffer_) {}
+
+AudioLogMessage::~AudioLogMessage() {
+  BufferManager::Get()->Dispose(buffer_);
+}
+
+void InitializeAudioLog() {
+  BufferManager::Get()->Setup();
+}
+
+}  // namespace logging

chromecast/media/audio/audio_log.h

+// Copyright 2020 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.
+
+#ifndef CHROMECAST_MEDIA_AUDIO_AUDIO_LOG_H_
+#define CHROMECAST_MEDIA_AUDIO_AUDIO_LOG_H_
+
+#include <ostream>
+
+#include "base/logging.h"
+
+namespace logging {
+
+#define AUDIO_LOG_STREAM(severity) \
+  COMPACT_GOOGLE_LOG_EX_##severity(AudioLogMessage).stream()
+
+#define AUDIO_LOG(severity) \
+  LAZY_STREAM(AUDIO_LOG_STREAM(severity), LOG_IS_ON(severity))
+
+#define AUDIO_LOG_IF(severity, condition) \
+  LAZY_STREAM(AUDIO_LOG_STREAM(severity), LOG_IS_ON(severity) && (condition))
+
+class AudioLogMessage {
+ public:
+  class StreamBuf;
+
+  AudioLogMessage(const char* file, int line, LogSeverity severity);
+  ~AudioLogMessage();
+
+  AudioLogMessage(const AudioLogMessage&) = delete;
+  AudioLogMessage& operator=(const AudioLogMessage&) = delete;
+
+  std::ostream& stream() { return stream_; }
+
+ private:
+  StreamBuf* buffer_;
+  std::ostream stream_;
+};
+
+// Should be called on a lower-priority thread. Actual output of log messages
+// will be done on this thread. Note that any use of AudioLogMessage prior to
+// InitializeAudioLog() will not produce any output.
+void InitializeAudioLog();
+
+}  // namespace logging
+
+#endif  // CHROMECAST_MEDIA_AUDIO_AUDIO_LOG_H_

chromecast/media/cma/backend/mixer/BUILD.gn

@@ -72,6 +72,7 @@ cast_source_set("mixer") {
     "//chromecast/base:chromecast_switches",
     "//chromecast/base:thread_health_checker",
     "//chromecast/media/audio:audio_io_thread",
+    "//chromecast/media/audio:audio_log",
     "//chromecast/media/audio:interleaved_channel_mixer",
     "//chromecast/media/audio:libcast_external_audio_pipeline_1.0",
     "//chromecast/media/audio:processing",

chromecast/media/cma/backend/mixer/audio_output_redirector.cc

@@ -16,6 +16,7 @@
 #include "base/strings/pattern.h"
 #include "base/threading/sequenced_task_runner_handle.h"
 #include "chromecast/media/audio/audio_fader.h"
+#include "chromecast/media/audio/audio_log.h"
 #include "chromecast/media/audio/mixer_service/conversions.h"
 #include "chromecast/media/audio/mixer_service/mixer_service.pb.h"
 #include "chromecast/media/audio/mixer_service/mixer_socket.h"
@@ -183,8 +184,9 @@ AudioOutputRedirector::InputImpl::InputImpl(
   DCHECK(mixer_input_);
 
   if (mixer_input_->num_channels() != num_output_channels_) {
-    LOG(INFO) << "Remixing channels for " << mixer_input_->source() << " from "
-              << mixer_input_->num_channels() << " to " << num_output_channels_;
+    AUDIO_LOG(INFO) << "Remixing channels for " << mixer_input_->source()
+                    << " from " << mixer_input_->num_channels() << " to "
+                    << num_output_channels_;
     channel_mixer_ = std::make_unique<::media::ChannelMixer>(
         mixer::CreateAudioParametersForChannelMixer(
             mixer_input_->channel_layout(), mixer_input_->num_channels()),

chromecast/media/cma/backend/mixer/filter_group.cc

@@ -11,6 +11,7 @@
 #include "base/numerics/ranges.h"
 #include "base/time/time.h"
 #include "base/values.h"
+#include "chromecast/media/audio/audio_log.h"
 #include "chromecast/media/audio/interleaved_channel_mixer.h"
 #include "chromecast/media/cma/backend/mixer/channel_layout.h"
 #include "chromecast/media/cma/backend/mixer/mixer_input.h"
@@ -124,15 +125,16 @@ void FilterGroup::ParseVolumeLimits(const base::Value* volume_limits) {
   // Get default limits.
   if (ParseVolumeLimit(volume_limits, &default_volume_min_,
                        &default_volume_max_)) {
-    LOG(INFO) << "Default volume limits for '" << name_ << "' group: ["
-              << default_volume_min_ << ", " << default_volume_max_ << "]";
+    AUDIO_LOG(INFO) << "Default volume limits for '" << name_ << "' group: ["
+                    << default_volume_min_ << ", " << default_volume_max_
+                    << "]";
   }
 
   float min, max;
   for (const auto& item : volume_limits->DictItems()) {
     if (ParseVolumeLimit(&item.second, &min, &max)) {
-      LOG(INFO) << "Volume limits for device ID '" << item.first << "' = ["
-                << min << ", " << max << "]";
+      AUDIO_LOG(INFO) << "Volume limits for device ID '" << item.first
+                      << "' = [" << min << ", " << max << "]";
       volume_limits_.insert({item.first, {min, max}});
     }
   }
@@ -290,8 +292,8 @@ void FilterGroup::SetPostProcessorConfig(const std::string& name,
 
 void FilterGroup::UpdatePlayoutChannel(int playout_channel) {
   if (playout_channel >= num_channels_) {
-    LOG(ERROR) << "only " << num_channels_ << " present, wanted channel #"
-               << playout_channel;
+    AUDIO_LOG(ERROR) << "only " << num_channels_ << " present, wanted channel #"
+                     << playout_channel;
     return;
   }
   post_processing_pipeline_->UpdatePlayoutChannel(playout_channel);

chromecast/media/cma/backend/mixer/mixer_input.cc

@@ -15,6 +15,7 @@
 #include "base/logging.h"
 #include "base/numerics/ranges.h"
 #include "chromecast/media/audio/audio_fader.h"
+#include "chromecast/media/audio/audio_log.h"
 #include "chromecast/media/cma/backend/mixer/audio_output_redirector_input.h"
 #include "chromecast/media/cma/backend/mixer/channel_layout.h"
 #include "chromecast/media/cma/backend/mixer/filter_group.h"
@@ -117,8 +118,9 @@ void MixerInput::SetFilterGroup(FilterGroup* filter_group) {
     if (filter_group->num_channels() == num_channels_) {
       channel_mixer_.reset();
     } else {
-      LOG(INFO) << "Remixing channels for " << source_ << " from "
-                << num_channels_ << " to " << filter_group->num_channels();
+      AUDIO_LOG(INFO) << "Remixing channels for " << source_ << " from "
+                      << num_channels_ << " to "
+                      << filter_group->num_channels();
       channel_mixer_ = std::make_unique<::media::ChannelMixer>(
           mixer::CreateAudioParametersForChannelMixer(channel_layout_,
                                                       num_channels_),
@@ -131,7 +133,8 @@ void MixerInput::SetFilterGroup(FilterGroup* filter_group) {
 
 void MixerInput::AddAudioOutputRedirector(
     AudioOutputRedirectorInput* redirector) {
-  LOG(INFO) << "Add redirector to " << device_id_ << "(" << source_ << ")";
+  AUDIO_LOG(INFO) << "Add redirector to " << device_id_ << "(" << source_
+                  << ")";
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
   DCHECK(redirector);
   audio_output_redirectors_.insert(
@@ -146,7 +149,8 @@ void MixerInput::AddAudioOutputRedirector(
 
 void MixerInput::RemoveAudioOutputRedirector(
     AudioOutputRedirectorInput* redirector) {
-  LOG(INFO) << "Remove redirector from " << device_id_ << "(" << source_ << ")";
+  AUDIO_LOG(INFO) << "Remove redirector from " << device_id_ << "(" << source_
+                  << ")";
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
   DCHECK(redirector);
   audio_output_redirectors_.erase(
@@ -323,9 +327,9 @@ void MixerInput::SetVolumeMultiplier(float multiplier) {
   float old_target_volume = TargetVolume();
   stream_volume_multiplier_ = std::max(0.0f, multiplier);
   float target_volume = TargetVolume();
-  LOG(INFO) << device_id_ << "(" << source_
-            << "): stream volume = " << stream_volume_multiplier_
-            << ", effective multiplier = " << target_volume;
+  AUDIO_LOG(INFO) << device_id_ << "(" << source_
+                  << "): stream volume = " << stream_volume_multiplier_
+                  << ", effective multiplier = " << target_volume;
   if (target_volume != old_target_volume) {
     slew_volume_.SetMaxSlewTimeMs(kDefaultSlewTimeMs);
     slew_volume_.SetVolume(target_volume);
@@ -339,9 +343,9 @@ void MixerInput::SetContentTypeVolume(float volume) {
   float old_target_volume = TargetVolume();
   type_volume_multiplier_ = volume;
   float target_volume = TargetVolume();
-  LOG(INFO) << device_id_ << "(" << source_
-            << "): type volume = " << type_volume_multiplier_
-            << ", effective multiplier = " << target_volume;
+  AUDIO_LOG(INFO) << device_id_ << "(" << source_
+                  << "): type volume = " << type_volume_multiplier_
+                  << ", effective multiplier = " << target_volume;
   if (target_volume != old_target_volume) {
     slew_volume_.SetMaxSlewTimeMs(kDefaultSlewTimeMs);
     slew_volume_.SetVolume(target_volume);
@@ -354,8 +358,8 @@ void MixerInput::SetVolumeLimits(float volume_min, float volume_max) {
   volume_min_ = volume_min;
   volume_max_ = volume_max;
   float target_volume = TargetVolume();
-  LOG(INFO) << device_id_ << "(" << source_ << "): set volume limits to ["
-            << volume_min_ << ", " << volume_max_ << "]";
+  AUDIO_LOG(INFO) << device_id_ << "(" << source_ << "): set volume limits to ["
+                  << volume_min_ << ", " << volume_max_ << "]";
   if (target_volume != old_target_volume) {
     slew_volume_.SetMaxSlewTimeMs(kDefaultSlewTimeMs);
     slew_volume_.SetVolume(target_volume);
@@ -367,13 +371,13 @@ void MixerInput::SetOutputLimit(float limit, int fade_ms) {
   float old_target_volume = TargetVolume();
   output_volume_limit_ = limit;
   float target_volume = TargetVolume();
-  LOG(INFO) << device_id_ << "(" << source_
-            << "): output limit = " << output_volume_limit_
-            << ", effective multiplier = " << target_volume;
+  AUDIO_LOG(INFO) << device_id_ << "(" << source_
+                  << "): output limit = " << output_volume_limit_
+                  << ", effective multiplier = " << target_volume;
   if (fade_ms < 0) {
     fade_ms = kDefaultSlewTimeMs;
   } else {
-    LOG(INFO) << "Fade over " << fade_ms << " ms";
+    AUDIO_LOG(INFO) << "Fade over " << fade_ms << " ms";
   }
   if (target_volume != old_target_volume) {
     slew_volume_.SetMaxSlewTimeMs(fade_ms);
@@ -388,9 +392,9 @@ void MixerInput::SetMuted(bool muted) {
   float old_target_volume = TargetVolume();
   mute_volume_multiplier_ = muted ? 0.0f : 1.0f;
   float target_volume = TargetVolume();
-  LOG(INFO) << device_id_ << "(" << source_
-            << "): mute volume = " << mute_volume_multiplier_
-            << ", effective multiplier = " << target_volume;
+  AUDIO_LOG(INFO) << device_id_ << "(" << source_
+                  << "): mute volume = " << mute_volume_multiplier_
+                  << ", effective multiplier = " << target_volume;
   if (target_volume != old_target_volume) {
     slew_volume_.SetMaxSlewTimeMs(kDefaultSlewTimeMs);
     slew_volume_.SetVolume(target_volume);

chromecast/media/cma/backend/mixer/mixer_input_connection.cc

@@ -19,6 +19,7 @@
 #include "base/threading/thread_task_runner_handle.h"
 #include "base/time/time.h"
 #include "chromecast/base/chromecast_switches.h"
+#include "chromecast/media/audio/audio_log.h"
 #include "chromecast/media/audio/mixer_service/conversions.h"
 #include "chromecast/media/audio/mixer_service/mixer_service.pb.h"
 #include "chromecast/media/cma/backend/mixer/channel_layout.h"
@@ -583,7 +584,7 @@ void MixerInputConnection::WritePcm(scoped_refptr<net::IOBuffer> data) {
 int64_t MixerInputConnection::QueueData(scoped_refptr<net::IOBuffer> data) {
   int frames = GetFrameCount(data.get());
   if (frames == 0) {
-    LOG(INFO) << "End of stream for " << this;
+    AUDIO_LOG(INFO) << "End of stream for " << this;
     state_ = State::kGotEos;
     if (!started_) {
       io_task_runner_->PostTask(FROM_HERE, ready_for_playback_task_);
@@ -656,8 +657,8 @@ void MixerInputConnection::InitializeAudioPlayback(
     mixer_read_size_ = read_size;
     if (start_threshold_frames_ == 0) {
       start_threshold_frames_ = read_size + fill_size_;
-      LOG(INFO) << this
-                << " Updated start threshold: " << start_threshold_frames_;
+      AUDIO_LOG(INFO) << this << " Updated start threshold: "
+                      << start_threshold_frames_;
     }
     mixer_rendering_delay_ = initial_rendering_delay;
     if (state_ == State::kUninitialized) {
@@ -687,8 +688,8 @@ void MixerInputConnection::CheckAndStartPlaybackIfNecessary(
   const int frames_needed_to_start = std::max(
       start_threshold_frames_, fader_.FramesNeededFromSource(num_frames));
   if (max_queued_frames_ < frames_needed_to_start) {
-    LOG(INFO) << "Boost queue size to " << frames_needed_to_start
-              << " to allow stream to start";
+    AUDIO_LOG(INFO) << "Boost queue size to " << frames_needed_to_start
+                    << " to allow stream to start";
     max_queued_frames_ = frames_needed_to_start;
   }
   const bool have_enough_queued_frames =
@@ -700,7 +701,7 @@ void MixerInputConnection::CheckAndStartPlaybackIfNecessary(
   remaining_silence_frames_ = 0;
   if (!use_start_timestamp_ || (queue_.empty() && state_ == State::kGotEos)) {
     // No start timestamp, so start as soon as there are enough queued frames.
-    LOG(INFO) << "Start " << this;
+    AUDIO_LOG(INFO) << "Start " << this;
     started_ = true;
     return;
   }
@@ -726,7 +727,7 @@ void MixerInputConnection::CheckAndStartPlaybackIfNecessary(
   int64_t drop_us = (desired_pts_now - actual_pts_now) / playback_rate_;
 
   if (drop_us >= 0) {
-    LOG(INFO) << this << " Dropping audio, duration = " << drop_us;
+    AUDIO_LOG(INFO) << this << " Dropping audio, duration = " << drop_us;
     DropAudio(::media::AudioTimestampHelper::TimeToFrames(
         base::TimeDelta::FromMicroseconds(drop_us), input_samples_per_second_));
     // Only start if we still have enough data to do so.
@@ -738,20 +739,22 @@ void MixerInputConnection::CheckAndStartPlaybackIfNecessary(
                           SamplesToMicroseconds(current_buffer_offset_,
                                                 input_samples_per_second_) *
                               playback_rate_;
-      LOG(INFO) << this << " Start playback of PTS " << start_pts << " at "
-                << playback_absolute_timestamp;
+      AUDIO_LOG(INFO) << this << " Start playback of PTS " << start_pts
+                      << " at " << playback_absolute_timestamp;
     }
   } else {
     int64_t silence_duration = -drop_us;
-    LOG(INFO) << this << " Adding silence. Duration = " << silence_duration;
+    AUDIO_LOG(INFO) << this
+                    << " Adding silence. Duration = " << silence_duration;
     remaining_silence_frames_ = ::media::AudioTimestampHelper::TimeToFrames(
         base::TimeDelta::FromMicroseconds(silence_duration),
         input_samples_per_second_);
     // Round to nearest multiple of 4 to preserve buffer alignment.
     remaining_silence_frames_ = ((remaining_silence_frames_ + 2) / 4) * 4;
     started_ = true;
-    LOG(INFO) << this << " Should start playback of PTS " << actual_pts_now
-              << " at " << (playback_absolute_timestamp + silence_duration);
+    AUDIO_LOG(INFO) << this << " Should start playback of PTS "
+                    << actual_pts_now << " at "
+                    << (playback_absolute_timestamp + silence_duration);
   }
 }
 
@@ -774,7 +777,8 @@ void MixerInputConnection::DropAudio(int64_t frames_to_drop) {
   }
 
   if (frames_to_drop > 0) {
-    LOG(INFO) << this << " Still need to drop " << frames_to_drop << " frames";
+    AUDIO_LOG(INFO) << this << " Still need to drop " << frames_to_drop
+                    << " frames";
   }
 }
 
@@ -814,11 +818,11 @@ int MixerInputConnection::FillAudioPlaybackFrames(
     // full request. This will allow us to buffer up more data so we can fully
     // fade in.
     if (state_ == State::kNormalPlayback && !can_complete_fill) {
-      LOG_IF(INFO, !zero_fader_frames_) << "Stream underrun for " << this;
+      AUDIO_LOG_IF(INFO, !zero_fader_frames_) << "Stream underrun for " << this;
       zero_fader_frames_ = true;
       underrun = true;
     } else {
-      LOG_IF(INFO, started_ && zero_fader_frames_)
+      AUDIO_LOG_IF(INFO, started_ && zero_fader_frames_)
           << "Stream underrun recovered for " << this;
       zero_fader_frames_ = false;
       if (!skip_next_fill_for_rate_change_) {
@@ -932,8 +936,9 @@ bool MixerInputConnection::FillRateShifted(int needed_frames) {
   }
 
   if (rate_shifter_output_->frames() < needed_frames) {
-    LOG(WARNING) << "Rate shifter output is too small; "
-                 << rate_shifter_output_->frames() << " < " << needed_frames;
+    AUDIO_LOG(WARNING) << "Rate shifter output is too small; "
+                       << rate_shifter_output_->frames() << " < "
+                       << needed_frames;
     auto output = ::media::AudioBus::Create(num_channels_, needed_frames);
     rate_shifter_output_->CopyPartialFramesTo(0, rate_shifted_offset_, 0,
                                               output.get());
@@ -1044,7 +1049,7 @@ void MixerInputConnection::PostAudioReadyForPlayback() {
   if (audio_ready_for_playback_fired_) {
     return;
   }
-  LOG(INFO) << this << " ready for playback";
+  AUDIO_LOG(INFO) << this << " ready for playback";
 
   mixer_service::Generic message;
   auto* ready_for_playback = message.mutable_ready_for_playback();
@@ -1075,8 +1080,8 @@ void MixerInputConnection::PostOutputUnderrun() {
 
 void MixerInputConnection::OnAudioPlaybackError(MixerError error) {
   if (error == MixerError::kInputIgnored) {
-    LOG(INFO) << "Mixer input " << this
-              << " now being ignored due to output sample rate change";
+    AUDIO_LOG(INFO) << "Mixer input " << this
+                    << " now being ignored due to output sample rate change";
   }
 
   io_task_runner_->PostTask(

chromecast/media/cma/backend/mixer/stream_mixer.cc

@@ -25,6 +25,7 @@
 #include "chromecast/base/serializers.h"
 #include "chromecast/base/thread_health_checker.h"
 #include "chromecast/media/audio/audio_io_thread.h"
+#include "chromecast/media/audio/audio_log.h"
 #include "chromecast/media/audio/interleaved_channel_mixer.h"
 #include "chromecast/media/audio/mixer_service/loopback_interrupt_reason.h"
 #include "chromecast/media/base/audio_device_ids.h"
@@ -220,6 +221,9 @@ StreamMixer::StreamMixer(
     io_task_runner_ = mixer_task_runner_;
   }
 
+  io_task_runner_->PostTask(FROM_HERE,
+                            base::BindOnce(&logging::InitializeAudioLog));
+
   if (fixed_output_sample_rate_ != MixerOutputStream::kInvalidSampleRate) {
     LOG(INFO) << "Setting fixed sample rate to " << fixed_output_sample_rate_;
   }
@@ -307,8 +311,8 @@ void StreamMixer::CreatePostProcessors(CastMediaShlib::ResultCallback callback,
   // Attempt to fall back to built-in cast_audio.json, unless we were reset with
   // an override config.
   if (!mixer_pipeline_ && override_config.empty()) {
-    LOG(WARNING) << "Invalid cast_audio.json config loaded. Retrying with "
-                    "read-only config";
+    AUDIO_LOG(WARNING) << "Invalid cast_audio.json config loaded. Retrying with"
+                          " read-only config";
     callback(false,
              "Unable to build pipeline.");  // TODO(bshaya): Send more specific
                                             // error message.
@@ -325,10 +329,11 @@ void StreamMixer::CreatePostProcessors(CastMediaShlib::ResultCallback callback,
       fixed_num_output_channels_ != mixer_pipeline_->GetOutputChannelCount()) {
     // Just log a warning, but this is still fine because we will remap the
     // channels prior to output.
-    LOG(WARNING) << "PostProcessor configuration output channel count does not "
-                 << "match command line flag: "
-                 << mixer_pipeline_->GetOutputChannelCount() << " vs "
-                 << fixed_num_output_channels_ << ". Channels will be remapped";
+    AUDIO_LOG(WARNING) << "PostProcessor configuration output channel count"
+                       << " does not match command line flag: "
+                       << mixer_pipeline_->GetOutputChannelCount() << " vs "
+                       << fixed_num_output_channels_
+                       << ". Channels will be remapped";
   }
 
   if (state_ == kStateRunning) {
@@ -397,7 +402,7 @@ void StreamMixer::SetNumOutputChannels(int num_channels) {
 }
 
 void StreamMixer::SetNumOutputChannelsOnThread(int num_channels) {
-  LOG(INFO) << "Set the number of output channels to " << num_channels;
+  AUDIO_LOG(INFO) << "Set the number of output channels to " << num_channels;
   enable_dynamic_channel_count_ = true;
   fixed_num_output_channels_ = num_channels;
 
@@ -408,7 +413,7 @@ void StreamMixer::SetNumOutputChannelsOnThread(int num_channels) {
 }
 
 void StreamMixer::Start() {
-  LOG(INFO) << __func__ << " with " << inputs_.size() << " active inputs";
+  AUDIO_LOG(INFO) << __func__ << " with " << inputs_.size() << " active inputs";
   DCHECK(mixer_task_runner_->BelongsToCurrentThread());
   DCHECK(state_ == kStateStopped);
 
@@ -458,9 +463,9 @@ void StreamMixer::Start() {
 
   num_output_channels_ = output_->GetNumChannels();
   output_samples_per_second_ = output_->GetSampleRate();
-  LOG(INFO) << "Output " << num_output_channels_ << " "
-            << ChannelString(num_output_channels_) << " at "
-            << output_samples_per_second_ << " samples per second";
+  AUDIO_LOG(INFO) << "Output " << num_output_channels_ << " "
+                  << ChannelString(num_output_channels_) << " at "
+                  << output_samples_per_second_ << " samples per second";
   // Make sure the number of frames meets the filter alignment requirements.
   frames_per_write_ =
       output_->OptimalWriteFramesCount() & ~(filter_frame_alignment_ - 1);
@@ -476,8 +481,8 @@ void StreamMixer::Start() {
   if (!enable_dynamic_channel_count_ && num_output_channels_ == 1) {
     num_loopback_channels = 1;
   }
-  LOG(INFO) << "Using " << num_loopback_channels << " loopback "
-            << ChannelString(num_loopback_channels);
+  AUDIO_LOG(INFO) << "Using " << num_loopback_channels << " loopback "
+                  << ChannelString(num_loopback_channels);
   loopback_channel_mixer_ = std::make_unique<InterleavedChannelMixer>(
       mixer::GuessChannelLayout(mixer_pipeline_->GetLoopbackChannelCount()),
       mixer_pipeline_->GetLoopbackChannelCount(),
@@ -533,7 +538,7 @@ void StreamMixer::Start() {
 }
 
 void StreamMixer::Stop(LoopbackInterruptReason reason) {
-  LOG(INFO) << __func__;
+  AUDIO_LOG(INFO) << __func__;
   DCHECK(mixer_task_runner_->BelongsToCurrentThread());
 
   weak_factory_.InvalidateWeakPtrs();
@@ -596,9 +601,10 @@ void StreamMixer::SignalError(MixerInput::Source::MixerError error) {
 }
 
 int StreamMixer::GetEffectiveChannelCount(MixerInput::Source* input_source) {
-  LOG(INFO) << "Input source channel count = " << input_source->num_channels();
+  AUDIO_LOG(INFO) << "Input source channel count = "
+                  << input_source->num_channels();
   if (!enable_dynamic_channel_count_) {
-    LOG(INFO) << "Dynamic channel count not enabled; using stereo";
+    AUDIO_LOG(INFO) << "Dynamic channel count not enabled; using stereo";
     return kDefaultInputChannels;
   }
 
@@ -631,10 +637,11 @@ void StreamMixer::AddInput(MixerInput::Source* input_source) {
   DCHECK(input_group) << "Could not find a processor for "
                       << input_source->device_id();
 
-  LOG(INFO) << "Add input " << input_source << " to " << input_group->name()
-            << " @ " << input_group->GetInputSampleRate()
-            << " samples per second. Is primary source? = "
-            << input_source->primary();
+  AUDIO_LOG(INFO) << "Add input " << input_source << " to "
+                  << input_group->name() << " @ "
+                  << input_group->GetInputSampleRate()
+                  << " samples per second. Is primary source? = "
+                  << input_source->primary();
 
   auto input = std::make_unique<MixerInput>(input_source, input_group);
   if (state_ != kStateRunning) {
@@ -673,7 +680,7 @@ void StreamMixer::RemoveInputOnThread(MixerInput::Source* input_source) {
   DCHECK(mixer_task_runner_->BelongsToCurrentThread());
   DCHECK(input_source);
 
-  LOG(INFO) << "Remove input " << input_source;
+  AUDIO_LOG(INFO) << "Remove input " << input_source;
 
   auto it = inputs_.find(input_source);
   if (it != inputs_.end()) {
@@ -719,7 +726,7 @@ void StreamMixer::UpdatePlayoutChannel() {
   }
 
   DCHECK(playout_channel == kChannelAll || playout_channel >= 0);
-  LOG(INFO) << "Update playout channel: " << playout_channel;
+  AUDIO_LOG(INFO) << "Update playout channel: " << playout_channel;
   playout_channel_ = playout_channel;
   mixer_pipeline_->SetPlayoutChannel(playout_channel_);
 }
@@ -764,7 +771,7 @@ void StreamMixer::PlaybackLoop() {
   DCHECK(mixer_task_runner_->BelongsToCurrentThread());
   if (inputs_.empty() && base::TimeTicks::Now() >= close_timestamp_ &&
       !mixer_pipeline_->IsRinging()) {
-    LOG(INFO) << "Close timeout";
+    AUDIO_LOG(INFO) << "Close timeout";
     Stop(LoopbackInterruptReason::kOutputStopped);
     return;
   }
@@ -843,7 +850,7 @@ void StreamMixer::WriteMixedPcm(int frames, int64_t expected_playback_time) {
 void StreamMixer::AddAudioOutputRedirector(
     std::unique_ptr<AudioOutputRedirector> redirector) {
   MAKE_SURE_MIXER_THREAD(AddAudioOutputRedirector, std::move(redirector));
-  LOG(INFO) << __func__;
+  AUDIO_LOG(INFO) << __func__;
   DCHECK(redirector);
 
   AudioOutputRedirector* key = redirector.get();
@@ -867,7 +874,7 @@ void StreamMixer::RemoveAudioOutputRedirector(
 void StreamMixer::RemoveAudioOutputRedirectorOnThread(
     AudioOutputRedirector* redirector) {
   DCHECK(mixer_task_runner_->BelongsToCurrentThread());
-  LOG(INFO) << __func__;
+  AUDIO_LOG(INFO) << __func__;
   audio_output_redirectors_.erase(redirector);
 }
 
@@ -908,7 +915,7 @@ void StreamMixer::SetOutputLimit(AudioContentType type, float limit) {
   MAKE_SURE_MIXER_THREAD(SetOutputLimit, type, limit);
   DCHECK(type != AudioContentType::kOther);
 
-  LOG(INFO) << "Set volume limit for " << type << " to " << limit;
+  AUDIO_LOG(INFO) << "Set volume limit for " << type << " to " << limit;
   volume_info_[type].limit = limit;
   int fade_ms = kUseDefaultFade;
   if (type == AudioContentType::kMedia) {