blob: 26c06fa0393bc629579c1e0da5d5a6607da4916b [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 <stdint.h>
#include <algorithm>
#include "base/bind.h"
#include "base/bind_helpers.h"
#include "base/compiler_specific.h"
#include "base/metrics/histogram_macros.h"
#include "base/numerics/safe_conversions.h"
#include "base/stl_util.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/stream_monitor.h"
using base::TimeDelta;
namespace audio {
namespace {
// Time in seconds between two successive measurements of audio power levels.
constexpr int kPowerMonitorLogIntervalSeconds = 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);
}
} // namespace
OutputController::ErrorStatisticsTracker::ErrorStatisticsTracker()
: 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() {
UMA_HISTOGRAM_LONG_TIMES("Media.OutputStreamDuration",
base::TimeTicks::Now() - start_time_);
UMA_HISTOGRAM_BOOLEAN("Media.AudioOutputController.CallbackError",
error_during_callback_);
}
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());
}
OutputController::OutputController(
media::AudioManager* audio_manager,
EventHandler* handler,
const media::AudioParameters& params,
const std::string& output_device_id,
SyncReader* sync_reader,
StreamMonitorCoordinator* stream_monitor_coordinator,
const base::UnguessableToken& processing_id)
: audio_manager_(audio_manager),
params_(params),
handler_(handler),
task_runner_(audio_manager->GetTaskRunner()),
construction_time_(base::TimeTicks::Now()),
output_device_id_(output_device_id),
stream_(NULL),
disable_local_output_(false),
volume_(1.0),
state_(kEmpty),
sync_reader_(sync_reader),
stream_monitor_coordinator_(stream_monitor_coordinator),
processing_id_(processing_id),
power_monitor_(
params.sample_rate(),
TimeDelta::FromMilliseconds(kPowerMeasurementTimeConstantMillis)),
weak_factory_for_stream_(this) {
DCHECK(audio_manager);
DCHECK(handler_);
DCHECK(sync_reader_);
DCHECK(task_runner_.get());
DCHECK(stream_monitor_coordinator_ || processing_id.is_empty());
}
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());
RecreateStreamWithTimingUMA(RecreateReason::INITIAL_STREAM);
return state_ == kCreated;
}
void OutputController::RecreateStreamWithTimingUMA(
OutputController::RecreateReason reason) {
SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.CreateTime");
RecreateStream(reason);
}
void OutputController::RecreateStream(OutputController::RecreateReason reason) {
DCHECK(task_runner_->BelongsToCurrentThread());
TRACE_EVENT1("audio", "OutputController::RecreateStream", "reason",
static_cast<int>(reason));
switch (reason) {
case RecreateReason::INITIAL_STREAM:
handler_->OnLog("OutputController::RecreateStream(initial stream)");
break;
case RecreateReason::DEVICE_CHANGE:
handler_->OnLog("OutputController::RecreateStream(device change)");
break;
case RecreateReason::LOCAL_OUTPUT_TOGGLE:
handler_->OnLog("OutputController::RecreateStream(local output toggle)");
break;
}
// Close() can be called before Create() is executed.
if (state_ == kClosed)
return;
StopCloseAndClearStream(); // Calls RemoveOutputDeviceChangeListener().
DCHECK_EQ(kEmpty, state_);
if (disable_local_output_) {
// 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_) {
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()) {
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.
state_ = kCreated;
if (processing_id_) {
// Ensure new monitors know that we're active.
stream_monitor_coordinator_->AddObserver(processing_id_, this);
// Ensure existing monitors do as well.
stream_monitor_coordinator_->ForEachMemberInGroup(
processing_id_,
base::BindRepeating(
[](OutputController* controller, StreamMonitor* monitor) {
monitor->OnStreamActive(controller);
},
this));
}
}
void OutputController::Play() {
DCHECK(task_runner_->BelongsToCurrentThread());
SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.PlayTime");
TRACE_EVENT0("audio", "OutputController::Play");
handler_->OnLog("OutputController::Play");
// We can start from created or paused state.
if (state_ != kCreated && state_ != kPaused)
return;
// Ask for first packet.
sync_reader_->RequestMoreData(base::TimeDelta(), base::TimeTicks(), 0);
state_ = kPlaying;
if (will_monitor_audio_levels()) {
last_audio_level_log_time_ = base::TimeTicks::Now();
}
stats_tracker_.emplace();
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("StopStream");
}
// 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());
SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.PauseTime");
TRACE_EVENT0("audio", "OutputController::Pause");
handler_->OnLog("OutputController::Pause");
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();
}
void OutputController::Close() {
DCHECK(task_runner_->BelongsToCurrentThread());
SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.CloseTime");
TRACE_EVENT0("audio", "OutputController::Close");
handler_->OnLog("OutputController::Close");
if (state_ != kClosed) {
StopCloseAndClearStream();
sync_reader_->Close();
state_ = kClosed;
}
}
void OutputController::SetVolume(double volume) {
DCHECK(task_runner_->BelongsToCurrentThread());
// 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";
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_).InSeconds() >
kPowerMonitorLogIntervalSeconds) {
LogAudioPowerLevel("OnMoreData");
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::LogAudioPowerLevel(const char* call_name) {
std::pair<float, bool> power_and_clip =
power_monitor_.ReadCurrentPowerAndClip();
handler_->OnLog(
base::StringPrintf("OutputController::%s: average audio level=%.2f dBFS",
call_name, power_and_clip.first));
}
void OutputController::OnError() {
// 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);
// Only notify and remove ourselves if startup was successful.
if (processing_id_ && state_ != kEmpty) {
// Don't send out activation messages for now.
stream_monitor_coordinator_->RemoveObserver(processing_id_, this);
// Ensure everyone monitoring us knows we're no-longer active.
stream_monitor_coordinator_->ForEachMemberInGroup(
processing_id_,
base::BindRepeating(
[](OutputController* controller, StreamMonitor* monitor) {
monitor->OnStreamInactive(controller);
},
this));
}
StopStream();
stream_->Close();
stats_tracker_.reset();
stream_ = NULL;
}
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::ContainsValue(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());
if (!disable_local_output_)
ToggleLocalOutput();
}
void OutputController::StopMuting() {
DCHECK(task_runner_->BelongsToCurrentThread());
if (disable_local_output_)
ToggleLocalOutput();
}
void OutputController::ToggleLocalOutput() {
DCHECK(task_runner_->BelongsToCurrentThread());
disable_local_output_ = !disable_local_output_;
// 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)
Play();
}
}
void OutputController::OnMemberJoinedGroup(StreamMonitor* monitor) {
// We're only observing the group when we're active.
monitor->OnStreamActive(this);
}
void OutputController::OnMemberLeftGroup(StreamMonitor* monitor) {
// Do nothing. The monitor will have already cleaned up.
}
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.
SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.DeviceChangeTime");
auto state_to_string = [](State state) {
switch (state) {
case kEmpty:
return "empty";
case kCreated:
return "created";
case kPlaying:
return "playing";
case kPaused:
return "paused";
case kClosed:
return "closed";
case kError:
return "error";
}
return "unknown";
};
handler_->OnLog(
base::StringPrintf("OutputController::OnDeviceChange while in state: %s",
state_to_string(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)
Play();
}
std::pair<float, bool> OutputController::ReadCurrentPowerAndClip() {
DCHECK(will_monitor_audio_levels());
return power_monitor_.ReadCurrentPowerAndClip();
}
} // namespace audio