#include "services/audio/output_controller.h"
#include <inttypes.h>
#include <stdio.h>
#include <algorithm>
#include <string>
#include <utility>
#include "base/compiler_specific.h"
#include "base/containers/contains.h"
#include "base/feature_list.h"
#include "base/functional/bind.h"
#include "base/functional/callback_helpers.h"
#include "base/logging.h"
#include "base/metrics/histogram_macros.h"
#include "base/numerics/safe_conversions.h"
#include "base/strings/stringprintf.h"
#include "base/strings/to_string.h"
#include "base/threading/platform_thread.h"
#include "base/trace_event/trace_event.h"
#include "build/build_config.h"
#include "media/base/audio_timestamp_helper.h"
#include "media/base/media_switches.h"
#include "media/media_buildflags.h"
#include "services/audio/device_listener_output_stream.h"
#include "base/hash/hash.h"
namespace audio {
namespace {
BASE_FEATURE(kAudioOutputControllerRequestBeforeRead,
base::FEATURE_DISABLED_BY_DEFAULT);
constexpr base::TimeDelta kPowerMonitorLogInterval = base::Seconds(15);
const char* StateToString(OutputController::State state) {
switch (state) {
case OutputController::kEmpty:
return "empty";
case OutputController::kCreated:
return "created";
case OutputController::kPlaying:
return "playing";
case OutputController::kPaused:
return "paused";
case OutputController::kClosed:
return "closed";
case OutputController::kError:
return "error";
}
return "unknown";
}
const char* ErrorTypeToString(
media::AudioOutputStream::AudioSourceCallback::ErrorType type) {
switch (type) {
case media::AudioOutputStream::AudioSourceCallback::ErrorType::kUnknown:
return "Unknown";
case media::AudioOutputStream::AudioSourceCallback::ErrorType::
kDeviceChange:
return "DeviceChange";
}
return "Invalid";
}
bool ShouldMonitorAudioLevels() {
#if BUILDFLAG(IS_ANDROID)
return base::FeatureList::IsEnabled(media::kEnableAudioMonitoringOnAndroid);
#elif BUILDFLAG(IS_IOS)
return false;
#else
return true;
#endif
}
}
OutputController::ErrorStatisticsTracker::ErrorStatisticsTracker(
OutputController* controller)
: controller_(controller),
start_time_(base::TimeTicks::Now()),
on_more_io_data_called_(0) {
wedge_timer_.Start(FROM_HERE, base::Seconds(5), this,
&ErrorStatisticsTracker::WedgeCheck);
}
OutputController::ErrorStatisticsTracker::~ErrorStatisticsTracker() {
const base::TimeDelta duration = base::TimeTicks::Now() - start_time_;
UMA_HISTOGRAM_LONG_TIMES("Media.OutputStreamDuration", duration);
UMA_HISTOGRAM_BOOLEAN("Media.AudioOutputController.CallbackError",
error_during_callback_);
if (controller_) {
controller_->SendLogMessage("StopStream => (duration=%" PRId64 " sec)",
duration.InSeconds());
const double glitch_percentage =
duration.is_zero()
? 0
: glitch_info_.duration.InSecondsF() / duration.InSecondsF();
controller_->SendLogMessage(
"StopStream => (glitches=[%s], glitch_percentage=%.3f%%)",
glitch_info_.ToString().c_str(), glitch_percentage * 100);
controller_->SendLogMessage("StopStream => (error_during_callback=%s)",
base::ToString(error_during_callback_).c_str());
}
}
void OutputController::ErrorStatisticsTracker::RegisterError() {
error_during_callback_ = true;
}
void OutputController::ErrorStatisticsTracker::OnMoreDataCalled(
const media::AudioGlitchInfo& glitch_info) {
glitch_info_ += glitch_info;
if (on_more_io_data_called_.IsZero())
on_more_io_data_called_.Increment();
}
void OutputController::ErrorStatisticsTracker::WedgeCheck() {
UMA_HISTOGRAM_BOOLEAN("Media.AudioOutputControllerPlaybackStartupSuccess",
on_more_io_data_called_.IsOne());
if (on_more_io_data_called_.IsOne()) {
if (controller_)
controller_->SendLogMessage("WedgeCheck => (stream is alive)");
}
}
OutputController::OutputController(
media::AudioManager* audio_manager,
EventHandler* handler,
const media::AudioParameters& params,
const std::string& output_device_id,
SyncReader* sync_reader,
ManagedDeviceOutputStreamCreateCallback
managed_device_output_stream_create_callback)
: audio_manager_(audio_manager),
params_(params),
managed_device_output_stream_create_callback_(
std::move(managed_device_output_stream_create_callback)),
handler_(handler),
task_runner_(audio_manager->GetTaskRunner()),
construction_time_(base::TimeTicks::Now()),
output_device_id_(output_device_id),
stream_(nullptr),
disable_local_output_(false),
volume_(1.0),
state_(kEmpty),
sync_reader_(sync_reader),
power_monitor_(params.sample_rate(),
base::Milliseconds(kPowerMeasurementTimeConstantMillis)),
request_before_read_(base::FeatureList::IsEnabled(
kAudioOutputControllerRequestBeforeRead)),
will_monitor_audio_levels_(ShouldMonitorAudioLevels()) {
DCHECK(audio_manager);
DCHECK(handler_);
DCHECK(sync_reader_);
DCHECK(task_runner_.get());
}
OutputController::~OutputController() {
DCHECK(task_runner_->BelongsToCurrentThread());
DCHECK_EQ(kClosed, state_);
DCHECK_EQ(nullptr, stream_);
DCHECK(snoopers_.empty());
UMA_HISTOGRAM_LONG_TIMES("Media.AudioOutputController.LifeTime",
base::TimeTicks::Now() - construction_time_);
}
bool OutputController::CreateStream() {
DCHECK(task_runner_->BelongsToCurrentThread());
SendLogMessage("%s([state=%s])", __func__, StateToString(state_));
RecreateStream(RecreateReason::INITIAL_STREAM);
SendLogMessage("%s => (state=%s)", __func__, StateToString(state_));
return state_ == kCreated;
}
void OutputController::ReportStreamCreationUma(
OutputController::RecreateReason reason,
StreamCreationResult result) {
switch (reason) {
case RecreateReason::INITIAL_STREAM:
UMA_HISTOGRAM_ENUMERATION(
"Media.AudioOutputController."
"ProxyStreamCreationResultForDeviceChange",
result);
return;
case RecreateReason::DEVICE_CHANGE:
UMA_HISTOGRAM_ENUMERATION(
"Media.AudioOutputController.ProxyStreamCreationResult", result);
return;
case RecreateReason::LOCAL_OUTPUT_TOGGLE:
return;
}
return;
}
const char* OutputController::RecreateReasonToString(
OutputController::RecreateReason reason) {
switch (reason) {
case RecreateReason::INITIAL_STREAM:
return "INITIAL_STREAM";
case RecreateReason::DEVICE_CHANGE:
return "DEVICE_CHANGE";
case RecreateReason::LOCAL_OUTPUT_TOGGLE:
return "LOCAL_OUTPUT_TOGGLE";
}
return "Invalid";
}
void OutputController::RecreateStream(OutputController::RecreateReason reason) {
DCHECK(task_runner_->BelongsToCurrentThread());
TRACE_EVENT1("audio", "OutputController::RecreateStream", "reason",
RecreateReasonToString(reason));
SendLogMessage("RecreateStream({reason = %s}, {params = [%s]}, [state = %s])",
RecreateReasonToString(reason),
params_.AsHumanReadableString().c_str(),
StateToString(state_));
if (state_ == kClosed)
return;
StopCloseAndClearStream();
DCHECK_EQ(kEmpty, state_);
if (disable_local_output_) {
SendLogMessage("%s => (WARNING: local output disabed, using a fake stream)",
__func__);
media::AudioParameters mute_params = params_;
mute_params.set_format(media::AudioParameters::AUDIO_FAKE);
stream_ = audio_manager_->MakeAudioOutputStream(
mute_params, std::string(),
base::DoNothing());
} else if (managed_device_output_stream_create_callback_) {
stream_ = managed_device_output_stream_create_callback_.Run(
output_device_id_, params_,
base::BindRepeating(&OutputController::ProcessDeviceChange,
base::Unretained(this)));
} else {
media::AudioOutputStream* stream =
audio_manager_->MakeAudioOutputStreamProxy(params_, output_device_id_);
if (stream) {
stream_ = new DeviceListenerOutputStream(
audio_manager_, stream,
base::BindRepeating(&OutputController::ProcessDeviceChange,
base::Unretained(this)));
}
}
if (!stream_) {
SendLogMessage("%s => (ERROR: failed to create output stream)", __func__);
state_ = kError;
ReportStreamCreationUma(reason, StreamCreationResult::kCreateFailed);
handler_->OnControllerError();
return;
}
if (!stream_->Open()) {
SendLogMessage("%s => (ERROR: failed to open the created output stream)",
__func__);
StopCloseAndClearStream();
state_ = kError;
ReportStreamCreationUma(reason, StreamCreationResult::kOpenFailed);
handler_->OnControllerError();
return;
}
state_ = kCreated;
ReportStreamCreationUma(reason, StreamCreationResult::kOk);
stream_->SetVolume(volume_);
}
void OutputController::Play() {
DCHECK(task_runner_->BelongsToCurrentThread());
TRACE_EVENT0("audio", "OutputController::Play");
SendLogMessage("%s([state=%s])", __func__, StateToString(state_));
if (state_ != kCreated && state_ != kPaused)
return;
StartStream();
}
void OutputController::StartStream() {
DCHECK(task_runner_->BelongsToCurrentThread());
DCHECK(state_ == kCreated || state_ == kPaused);
if (!request_before_read_) {
sync_reader_->RequestMoreData(base::TimeDelta(), base::TimeTicks(), {});
}
state_ = kPlaying;
SendLogMessage("%s => (state=%s)", __func__, StateToString(state_));
if (will_monitor_audio_levels_) {
last_audio_level_log_time_ = base::TimeTicks::Now();
}
stats_tracker_.emplace(this);
stream_->Start(this);
handler_->OnControllerPlaying();
}
void OutputController::StopStream() {
DCHECK(task_runner_->BelongsToCurrentThread());
if (state_ == kPlaying) {
stream_->Stop();
stats_tracker_.reset();
if (will_monitor_audio_levels_) {
LogAudioPowerLevel(__func__);
}
power_monitor_.Reset();
state_ = kPaused;
}
}
void OutputController::Pause() {
DCHECK(task_runner_->BelongsToCurrentThread());
TRACE_EVENT0("audio", "OutputController::Pause");
SendLogMessage("%s([state=%s])", __func__, StateToString(state_));
StopStream();
if (state_ != kPaused)
return;
sync_reader_->RequestMoreData(base::TimeDelta::Max(), base::TimeTicks(), {});
handler_->OnControllerPaused();
SendLogMessage("%s => (state=%s)", __func__, StateToString(state_));
}
void OutputController::Flush() {
DCHECK(task_runner_->BelongsToCurrentThread());
TRACE_EVENT0("audio", "OutputController::Flush");
SendLogMessage("%s([state=%s])", __func__, StateToString(state_));
if (state_ == kPlaying) {
handler_->OnControllerError();
return;
}
if (stream_) {
stream_->Flush();
}
SendLogMessage("%s => (state=%s)", __func__, StateToString(state_));
}
void OutputController::Close() {
DCHECK(task_runner_->BelongsToCurrentThread());
TRACE_EVENT0("audio", "OutputController::Close");
SendLogMessage("%s([state=%s])", __func__, StateToString(state_));
if (state_ != kClosed) {
StopCloseAndClearStream();
sync_reader_->Close();
state_ = kClosed;
}
SendLogMessage("%s => (state=%s)", __func__, StateToString(state_));
}
void OutputController::SetVolume(double volume) {
DCHECK(task_runner_->BelongsToCurrentThread());
SendLogMessage("%s({volume=%.2f} [state=%s])", __func__, volume,
StateToString(state_));
volume_ = volume;
switch (state_) {
case kCreated:
case kPlaying:
case kPaused:
stream_->SetVolume(volume_);
break;
default:
break;
}
}
int OutputController::OnMoreData(base::TimeDelta delay,
base::TimeTicks delay_timestamp,
const media::AudioGlitchInfo& glitch_info,
media::AudioBus* dest) {
return OnMoreData(delay, delay_timestamp, glitch_info, dest, false);
}
int OutputController::OnMoreData(base::TimeDelta delay,
base::TimeTicks delay_timestamp,
const media::AudioGlitchInfo& glitch_info,
media::AudioBus* dest,
bool is_mixing) {
TRACE_EVENT("audio", "OutputController::OnMoreData", "this",
static_cast<void*>(this), "delay_timestamp (ms)",
(delay_timestamp - base::TimeTicks()).InMillisecondsF(),
"playout_delay (ms)", delay.InMillisecondsF());
glitch_info.MaybeAddTraceEvent();
stats_tracker_->OnMoreDataCalled(glitch_info);
if (request_before_read_) {
sync_reader_->RequestMoreData(delay, delay_timestamp, glitch_info);
}
const bool received_data = sync_reader_->Read(dest, is_mixing);
const base::TimeTicks reference_time = delay_timestamp + delay;
if (!dest->is_bitstream_format()) {
base::AutoLock lock(snooper_lock_);
if (!snoopers_.empty()) {
TRACE_EVENT1("audio", "OutputController::BroadcastDataToSnoopers",
"reference_time (ms)",
(reference_time - base::TimeTicks()).InMillisecondsF());
for (Snooper* snooper : snoopers_) {
snooper->OnData(*dest, reference_time, volume_);
}
}
}
const int frames =
dest->is_bitstream_format() ? dest->GetBitstreamFrames() : dest->frames();
if (!request_before_read_) {
delay += media::AudioTimestampHelper::FramesToTime(frames,
params_.sample_rate());
sync_reader_->RequestMoreData(delay, delay_timestamp, glitch_info);
}
#if !BUILDFLAG(ENABLE_PLATFORM_DTS_AUDIO)
constexpr bool is_bitstream = false;
#else
const bool is_bitstream = params_.IsBitstreamFormat();
#endif
if (will_monitor_audio_levels_ && received_data && !is_bitstream) {
CHECK(!params_.IsBitstreamFormat());
power_monitor_.Scan(*dest, frames);
const auto now = base::TimeTicks::Now();
if ((now - last_audio_level_log_time_) > kPowerMonitorLogInterval) {
LogAudioPowerLevel(__func__);
last_audio_level_log_time_ = now;
}
}
return frames;
}
void OutputController::SendLogMessage(const char* format, ...) {
if (!handler_)
return;
va_list args;
va_start(args, format);
#if BUILDFLAG(ARKWEB_MEDIA)
handler_->OnLog("AOC::" + base::StringPrintV(format, args) +
base::StringPrintf(" [this_hash=%016x]",
base::FastHash(base::byte_span_from_ref(this))));
#else
handler_->OnLog("AOC::" + base::StringPrintV(format, args) +
base::StringPrintf(" [this=0x%" PRIXPTR "]",
reinterpret_cast<uintptr_t>(this)));
#endif
va_end(args);
}
void OutputController::LogAudioPowerLevel(const char* call_name) {
std::pair<float, bool> power_and_clip =
power_monitor_.ReadCurrentPowerAndClip();
SendLogMessage("%s => (average audio level=%.2f dBFS)", call_name,
power_and_clip.first);
}
void OutputController::OnError(ErrorType type) {
DCHECK(task_runner_->BelongsToCurrentThread());
SendLogMessage("%s({type=%s} [state=%s])", __func__, ErrorTypeToString(type),
StateToString(state_));
TRACE_EVENT0("audio", "OutputController::OnError");
DLOG(ERROR) << "OutputController::OnError";
if (state_ != kClosed) {
if (stats_tracker_)
stats_tracker_->RegisterError();
handler_->OnControllerError();
}
}
void OutputController::StopCloseAndClearStream() {
DCHECK(task_runner_->BelongsToCurrentThread());
if (stream_) {
StopStream();
stream_->Close();
stream_ = nullptr;
}
state_ = kEmpty;
}
const media::AudioParameters& OutputController::GetAudioParameters() const {
return params_;
}
void OutputController::StartSnooping(Snooper* snooper) {
DCHECK(task_runner_->BelongsToCurrentThread());
DCHECK(snooper);
DCHECK(!base::Contains(snoopers_, snooper));
base::AutoLock lock(snooper_lock_);
snoopers_.push_back(snooper);
}
void OutputController::StopSnooping(Snooper* snooper) {
DCHECK(task_runner_->BelongsToCurrentThread());
const auto it = std::ranges::find(snoopers_, snooper);
CHECK(it != snoopers_.end());
base::AutoLock lock(snooper_lock_);
*it = snoopers_.back();
snoopers_.pop_back();
}
void OutputController::StartMuting() {
DCHECK(task_runner_->BelongsToCurrentThread());
SendLogMessage("%s([state=%s])", __func__, StateToString(state_));
if (!disable_local_output_) {
ToggleLocalOutput();
}
}
void OutputController::StopMuting() {
DCHECK(task_runner_->BelongsToCurrentThread());
SendLogMessage("%s([state=%s])", __func__, StateToString(state_));
if (disable_local_output_) {
ToggleLocalOutput();
}
}
void OutputController::ToggleLocalOutput() {
DCHECK(task_runner_->BelongsToCurrentThread());
disable_local_output_ = !disable_local_output_;
SendLogMessage("%s({disable_local_output=%s} [state=%s])", __func__,
base::ToString(disable_local_output_).c_str(),
StateToString(state_));
if (stream_) {
const bool restore_playback = (state_ == kPlaying);
RecreateStream(RecreateReason::LOCAL_OUTPUT_TOGGLE);
if (state_ == kCreated && restore_playback)
StartStream();
}
}
void OutputController::ProcessDeviceChange() {
DCHECK(task_runner_->BelongsToCurrentThread());
SendLogMessage("%s([state=%s])", __func__, StateToString(state_));
TRACE_EVENT0("audio", "OutputController::ProcessDeviceChange");
DCHECK(!disable_local_output_);
const bool restore_playback = (state_ == kPlaying);
RecreateStream(RecreateReason::DEVICE_CHANGE);
if (state_ == kCreated && restore_playback)
StartStream();
}
std::pair<float, bool> OutputController::ReadCurrentPowerAndClip() {
DCHECK(will_monitor_audio_levels_);
return power_monitor_.ReadCurrentPowerAndClip();
}
void OutputController::SwitchAudioOutputDeviceId(
const std::string& new_output_device_id) {
DCHECK(task_runner_->BelongsToCurrentThread());
if (output_device_id_ == new_output_device_id) {
return;
}
output_device_id_ = new_output_device_id;
ProcessDeviceChange();
}
}