blob: bf712c4a3df82838bdd85cde251fe5887e906a55 [file] [log] [blame]
// 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 "services/audio/output_controller.h"
#include <inttypes.h>
#include <stdio.h>
#include <algorithm>
#include <string>
#include <utility>
#include "base/bind.h"
#include "base/callback_helpers.h"
#include "base/compiler_specific.h"
#include "base/containers/contains.h"
#include "base/logging.h"
#include "base/metrics/histogram_macros.h"
#include "base/numerics/safe_conversions.h"
#include "base/strings/stringprintf.h"
#include "base/task_runner_util.h"
#include "base/threading/platform_thread.h"
#include "base/trace_event/trace_event.h"
#include "media/base/audio_timestamp_helper.h"
#include "services/audio/concurrent_stream_metric_reporter.h"
#include "services/audio/stream_monitor.h"
using base::TimeDelta;
namespace audio {
namespace {
// Time in seconds between two successive measurements of audio power levels.
constexpr base::TimeDelta kPowerMonitorLogInterval =
base::TimeDelta::FromSeconds(15);
// Used to log the result of rendering startup.
// Elements in this enum should not be deleted or rearranged; the only
// permitted operation is to add new elements before
// STREAM_CREATION_RESULT_MAX and update STREAM_CREATION_RESULT_MAX.
enum StreamCreationResult {
STREAM_CREATION_OK = 0,
STREAM_CREATION_CREATE_FAILED = 1,
STREAM_CREATION_OPEN_FAILED = 2,
STREAM_CREATION_RESULT_MAX = STREAM_CREATION_OPEN_FAILED,
};
void LogStreamCreationForDeviceChangeResult(StreamCreationResult result) {
UMA_HISTOGRAM_ENUMERATION(
"Media.AudioOutputController.ProxyStreamCreationResultForDeviceChange",
result, STREAM_CREATION_RESULT_MAX + 1);
}
void LogInitialStreamCreationResult(StreamCreationResult result) {
UMA_HISTOGRAM_ENUMERATION(
"Media.AudioOutputController.ProxyStreamCreationResult", result,
STREAM_CREATION_RESULT_MAX + 1);
}
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";
}
} // namespace
OutputController::ErrorStatisticsTracker::ErrorStatisticsTracker(
OutputController* controller)
: controller_(controller),
start_time_(base::TimeTicks::Now()),
on_more_io_data_called_(0) {
// WedgeCheck() will look to see if |on_more_io_data_called_| is true after
// the timeout expires and log this as a UMA stat. If the stream is
// paused/closed before the timer fires, nothing is logged.
wedge_timer_.Start(FROM_HERE, TimeDelta::FromSeconds(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());
controller_->SendLogMessage("StopStream => (error_during_callback=%s)",
error_during_callback_ ? "true" : "false");
}
}
void OutputController::ErrorStatisticsTracker::RegisterError() {
error_during_callback_ = true;
}
void OutputController::ErrorStatisticsTracker::OnMoreDataCalled() {
// Indicate that we haven't wedged (at least not indefinitely, WedgeCheck()
// may have already fired if OnMoreData() took an abnormal amount of time).
// Since this thread is the only writer of |on_more_io_data_called_| once the
// thread starts, it's safe to compare and then increment.
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,
OutputStreamActivityMonitor* activity_monitor,
const media::AudioParameters& params,
const std::string& output_device_id,
SyncReader* sync_reader)
: audio_manager_(audio_manager),
params_(params),
handler_(handler),
activity_monitor_(activity_monitor),
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(),
TimeDelta::FromMilliseconds(kPowerMeasurementTimeConstantMillis)) {
DCHECK(audio_manager);
DCHECK(handler_);
DCHECK(activity_monitor_);
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_));
RecreateStreamWithTimingUMA(RecreateReason::INITIAL_STREAM);
SendLogMessage("%s => (state=%s)", __func__, StateToString(state_));
return state_ == kCreated;
}
void OutputController::RecreateStreamWithTimingUMA(
OutputController::RecreateReason reason) {
RecreateStream(reason);
}
void OutputController::RecreateStream(OutputController::RecreateReason reason) {
DCHECK(task_runner_->BelongsToCurrentThread());
TRACE_EVENT1("audio", "OutputController::RecreateStream", "reason",
static_cast<int>(reason));
std::string str = "RecreateStream({reason=";
switch (reason) {
case RecreateReason::INITIAL_STREAM:
base::StringAppendF(&str, "INITIAL_STREAM}, ");
break;
case RecreateReason::DEVICE_CHANGE:
base::StringAppendF(&str, "DEVICE_CHANGE}, ");
break;
case RecreateReason::LOCAL_OUTPUT_TOGGLE:
base::StringAppendF(&str, "LOCAL_OUTPUT_TOGGLE}, ");
break;
}
base::StringAppendF(&str, "{params=[%s]} [state=%s])",
params_.AsHumanReadableString().c_str(),
StateToString(state_));
SendLogMessage("%s", str.c_str());
// Close() can be called before Create() is executed.
if (state_ == kClosed)
return;
StopCloseAndClearStream(); // Calls RemoveOutputDeviceChangeListener().
DCHECK_EQ(kEmpty, state_);
if (disable_local_output_) {
SendLogMessage("%s => (WARNING: using a fake audio output stream)",
__func__);
// Create a fake AudioOutputStream that will continue pumping the audio
// data, but does not play it out anywhere. Pumping the audio data is
// necessary because video playback is synchronized to the audio stream and
// will freeze otherwise.
media::AudioParameters mute_params = params_;
mute_params.set_format(media::AudioParameters::AUDIO_FAKE);
stream_ = audio_manager_->MakeAudioOutputStream(
mute_params, std::string(),
/*log_callback, not used*/ base::DoNothing());
} else {
stream_ =
audio_manager_->MakeAudioOutputStreamProxy(params_, output_device_id_);
}
if (!stream_) {
SendLogMessage("%s => (ERROR: failed to create output stream)", __func__);
state_ = kError;
// TODO(crbug.com/896484): Results should be counted iff the |stream_| is
// not a fake one. The |reason| for a non-fake stream to be created doesn't
// matter, right?
switch (reason) {
case RecreateReason::INITIAL_STREAM:
LogInitialStreamCreationResult(STREAM_CREATION_CREATE_FAILED);
break;
case RecreateReason::DEVICE_CHANGE:
LogStreamCreationForDeviceChangeResult(STREAM_CREATION_CREATE_FAILED);
break;
case RecreateReason::LOCAL_OUTPUT_TOGGLE:
break; // Not counted in UMAs.
}
handler_->OnControllerError();
return;
}
weak_this_for_stream_ = weak_factory_for_stream_.GetWeakPtr();
if (!stream_->Open()) {
SendLogMessage("%s => (ERROR: failed to open the created output stream)",
__func__);
StopCloseAndClearStream();
// TODO(crbug.com/896484): Here too.
switch (reason) {
case RecreateReason::INITIAL_STREAM:
LogInitialStreamCreationResult(STREAM_CREATION_OPEN_FAILED);
break;
case RecreateReason::DEVICE_CHANGE:
LogStreamCreationForDeviceChangeResult(STREAM_CREATION_OPEN_FAILED);
break;
case RecreateReason::LOCAL_OUTPUT_TOGGLE:
break; // Not counted in UMAs.
}
state_ = kError;
handler_->OnControllerError();
return;
}
// TODO(crbug.com/896484): Here three.
switch (reason) {
case RecreateReason::INITIAL_STREAM:
LogInitialStreamCreationResult(STREAM_CREATION_OK);
break;
case RecreateReason::DEVICE_CHANGE:
LogStreamCreationForDeviceChangeResult(STREAM_CREATION_OK);
break;
case RecreateReason::LOCAL_OUTPUT_TOGGLE:
break; // Not counted in UMAs.
}
audio_manager_->AddOutputDeviceChangeListener(this);
// We have successfully opened the stream. Set the initial volume.
stream_->SetVolume(volume_);
// Finally set the state to kCreated. Note that, it is possible that the
// stream is fake in this state due to the fallback mechanism in the audio
// output dispatcher which falls back to a fake stream if audio parameters
// are invalid or if a physical stream can't be opened for some reason.
state_ = kCreated;
}
void OutputController::Play() {
DCHECK(task_runner_->BelongsToCurrentThread());
TRACE_EVENT0("audio", "OutputController::Play");
SendLogMessage("%s([state=%s])", __func__, StateToString(state_));
// We can start from created or paused state.
if (state_ != kCreated && state_ != kPaused)
return;
StartStream();
if (StreamIsActive())
activity_monitor_->OnOutputStreamActive();
}
void OutputController::StartStream() {
DCHECK(task_runner_->BelongsToCurrentThread());
DCHECK(state_ == kCreated || state_ == kPaused);
// Ask for first packet.
sync_reader_->RequestMoreData(base::TimeDelta(), base::TimeTicks(), 0);
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();
// Destructor of ErrorStatisticsTracker also adds a log message.
stats_tracker_.reset();
if (will_monitor_audio_levels()) {
LogAudioPowerLevel(__func__);
}
// A stopped stream is silent, and power_montior_.Scan() is no longer being
// called; so we must reset the power monitor.
power_monitor_.Reset();
state_ = kPaused;
}
}
void OutputController::Pause() {
DCHECK(task_runner_->BelongsToCurrentThread());
TRACE_EVENT0("audio", "OutputController::Pause");
SendLogMessage("%s([state=%s])", __func__, StateToString(state_));
if (StreamIsActive())
activity_monitor_->OnOutputStreamInactive();
StopStream();
if (state_ != kPaused)
return;
// Let the renderer know we've stopped. Necessary to let PPAPI clients know
// audio has been shutdown. TODO(dalecurtis): This stinks. PPAPI should have
// a better way to know when it should exit PPB_Audio_Shared::Run().
sync_reader_->RequestMoreData(base::TimeDelta::Max(), base::TimeTicks(), 0);
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) {
if (StreamIsActive())
activity_monitor_->OnOutputStreamInactive();
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_));
// Saves the volume to a member first. We may not be able to set the volume
// right away but when the stream is created we'll set the volume.
volume_ = volume;
switch (state_) {
case kCreated:
case kPlaying:
case kPaused:
stream_->SetVolume(volume_);
break;
default:
break;
}
}
void OutputController::ReportError() {
DCHECK(task_runner_->BelongsToCurrentThread());
TRACE_EVENT0("audio", "OutputController::ReportError");
DLOG(ERROR) << "OutputController::ReportError";
SendLogMessage("%s([state=%s])", __func__, StateToString(state_));
if (state_ != kClosed) {
if (stats_tracker_)
stats_tracker_->RegisterError();
handler_->OnControllerError();
}
}
int OutputController::OnMoreData(base::TimeDelta delay,
base::TimeTicks delay_timestamp,
int prior_frames_skipped,
media::AudioBus* dest) {
TRACE_EVENT_BEGIN1("audio", "OutputController::OnMoreData", "frames skipped",
prior_frames_skipped);
stats_tracker_->OnMoreDataCalled();
sync_reader_->Read(dest);
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();
delay +=
media::AudioTimestampHelper::FramesToTime(frames, params_.sample_rate());
sync_reader_->RequestMoreData(delay, delay_timestamp, prior_frames_skipped);
if (will_monitor_audio_levels()) {
// Note: this code path should never be hit when using bitstream streams.
// Scan doesn't expect compressed audio, so it may go out of bounds trying
// to read |frames| frames of PCM data.
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;
}
}
TRACE_EVENT_END2("audio", "OutputController::OnMoreData", "timestamp (ms)",
(delay_timestamp - base::TimeTicks()).InMillisecondsF(),
"delay (ms)", delay.InMillisecondsF());
return frames;
}
void OutputController::SendLogMessage(const char* format, ...) {
if (!handler_)
return;
va_list args;
va_start(args, format);
handler_->OnLog("AOC::" + base::StringPrintV(format, args) +
base::StringPrintf(" [this=0x%" PRIXPTR "]",
reinterpret_cast<uintptr_t>(this)));
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);
}
bool OutputController::StreamIsActive() {
return (state_ == kPlaying) && !disable_local_output_;
}
void OutputController::OnError(ErrorType type) {
SendLogMessage("%s({type=%s} [state=%s])", __func__, ErrorTypeToString(type),
StateToString(state_));
if (type == ErrorType::kDeviceChange) {
task_runner_->PostTask(FROM_HERE,
base::BindOnce(&OutputController::OnDeviceChange,
weak_this_for_stream_));
return;
}
// Handle error on the audio controller thread. We defer errors for one
// second in case they are the result of a device change; delay chosen to
// exceed duration of device changes which take a few hundred milliseconds.
task_runner_->PostDelayedTask(
FROM_HERE,
base::BindOnce(&OutputController::ReportError, weak_this_for_stream_),
base::TimeDelta::FromSeconds(1));
}
void OutputController::StopCloseAndClearStream() {
DCHECK(task_runner_->BelongsToCurrentThread());
// Allow calling unconditionally and bail if we don't have a stream_ to close.
if (stream_) {
// Ensure any pending tasks, specific to the stream_, are canceled.
weak_factory_for_stream_.InvalidateWeakPtrs();
// De-register from state change callbacks if stream_ was created via
// AudioManager.
audio_manager_->RemoveOutputDeviceChangeListener(this);
StopStream();
stream_->Close();
stats_tracker_.reset();
stream_ = nullptr;
}
state_ = kEmpty;
}
const media::AudioParameters& OutputController::GetAudioParameters() const {
return params_;
}
std::string OutputController::GetDeviceId() const {
return output_device_id_.empty()
? media::AudioDeviceDescription::kDefaultDeviceId
: output_device_id_;
}
void OutputController::StartSnooping(Snooper* snooper) {
DCHECK(task_runner_->BelongsToCurrentThread());
DCHECK(snooper);
// The list will only update on this thread, and only be read on the realtime
// audio thread.
DCHECK(!base::Contains(snoopers_, snooper));
base::AutoLock lock(snooper_lock_);
snoopers_.push_back(snooper);
}
void OutputController::StopSnooping(Snooper* snooper) {
DCHECK(task_runner_->BelongsToCurrentThread());
// The list will only update on this thread, and only be read on the realtime
// audio thread.
const auto it = std::find(snoopers_.begin(), snoopers_.end(), snooper);
DCHECK(it != snoopers_.end());
// We also don't care about ordering, so swap and pop rather than erase.
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_) {
if (StreamIsActive())
activity_monitor_->OnOutputStreamInactive();
ToggleLocalOutput();
}
}
void OutputController::StopMuting() {
DCHECK(task_runner_->BelongsToCurrentThread());
SendLogMessage("%s([state=%s])", __func__, StateToString(state_));
if (disable_local_output_) {
ToggleLocalOutput();
if (StreamIsActive())
activity_monitor_->OnOutputStreamActive();
}
}
void OutputController::ToggleLocalOutput() {
DCHECK(task_runner_->BelongsToCurrentThread());
disable_local_output_ = !disable_local_output_;
SendLogMessage("%s({disable_local_output=%s} [state=%s])", __func__,
disable_local_output_ ? "true" : "false",
StateToString(state_));
// If there is an active |stream_|, close it and re-create either: 1) a fake
// stream to prevent local audio output, or 2) a normal AudioOutputStream.
if (stream_) {
const bool restore_playback = (state_ == kPlaying);
RecreateStream(RecreateReason::LOCAL_OUTPUT_TOGGLE);
if (state_ == kCreated && restore_playback)
StartStream();
}
}
void OutputController::OnDeviceChange() {
DCHECK(task_runner_->BelongsToCurrentThread());
TRACE_EVENT0("audio", "OutputController::OnDeviceChange");
if (disable_local_output_)
return; // No actions need to be taken while local output is disabled.
SendLogMessage("%s([state=%s])", __func__, StateToString(state_));
// TODO(dalecurtis): Notify the renderer side that a device change has
// occurred. Currently querying the hardware information here will lead to
// crashes on OSX. See http://crbug.com/158170.
const bool restore_playback = (state_ == kPlaying);
// TODO(crbug.com/896484): This will also add a UMA timing measurement to
// "Media.AudioOutputController.ChangeTime" which maybe is not desired?
RecreateStreamWithTimingUMA(RecreateReason::DEVICE_CHANGE);
if (state_ == kCreated && restore_playback)
StartStream();
}
std::pair<float, bool> OutputController::ReadCurrentPowerAndClip() {
DCHECK(will_monitor_audio_levels());
return power_monitor_.ReadCurrentPowerAndClip();
}
} // namespace audio