Reland of Avoid calling PostTask in audio callbacks (patchset #1 id:1 of https://codereview.webrtc.org/2684913003/ )

Reason for revert:
The reason for reverting was false alarm.

Original issue's description:
> Revert of Avoid calling PostTask in audio callbacks (patchset #6 id:100001 of https://codereview.webrtc.org/2663383004/ )
>
> Reason for revert:
> Speculative revert to see if this CL caused a change in performance tests.
>
> See https://bugs.chromium.org/p/chromium/issues/detail?id=689919 for details.
>
> Original issue's description:
> > Avoid calling PostTask in audio callbacks.
> >
> > We have seen that PostTask can consume some CPU and the way we used it
> > before (logging only) in the ADB is not worth the cost we see when
> > profiling.
> >
> > This CL simply moves frequent (trivial) stat updates from the task queue
> > to the native threads to avoid calling PostTask in each callback.
> > The reason for doing so before was to avoid locks but we can live without
> > them since races are benign here.
> >
> >
> > BUG=webrtc:7096
> >
> > Review-Url: https://codereview.webrtc.org/2663383004
> > Cr-Commit-Position: refs/heads/master@{#16429}
> > Committed: 77ce9a5541
>
> TBR=solenberg@webrtc.org
> # Not skipping CQ checks because original CL landed more than 1 days ago.
> BUG=webrtc:7096
>
> Review-Url: https://codereview.webrtc.org/2684913003
> Cr-Commit-Position: refs/heads/master@{#16490}
> Committed: fd8f102a84

TBR=solenberg@webrtc.org
# Skipping CQ checks because original CL landed less than 1 days ago.
NOPRESUBMIT=true
NOTREECHECKS=true
NOTRY=true
BUG=webrtc:7096

Review-Url: https://codereview.webrtc.org/2687573003
Cr-Commit-Position: refs/heads/master@{#16497}
This commit is contained in:
henrika
2017-02-08 07:16:56 -08:00
committed by Commit bot
parent 5d83780c42
commit 87d11cdbca
2 changed files with 90 additions and 100 deletions

View File

@ -53,21 +53,10 @@ AudioDeviceBuffer::AudioDeviceBuffer()
rec_delay_ms_(0),
clock_drift_(0),
num_stat_reports_(0),
rec_callbacks_(0),
last_rec_callbacks_(0),
play_callbacks_(0),
last_play_callbacks_(0),
rec_samples_(0),
last_rec_samples_(0),
play_samples_(0),
last_play_samples_(0),
max_rec_level_(0),
max_play_level_(0),
last_timer_task_time_(0),
rec_stat_count_(0),
play_stat_count_(0),
play_start_time_(0),
rec_start_time_(0),
only_silence_recorded_(true),
log_stats_(false) {
LOG(INFO) << "AudioDeviceBuffer::ctor";
@ -326,13 +315,9 @@ int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audio_buffer,
only_silence_recorded_ = false;
}
}
// Update some stats but do it on the task queue to ensure that the members
// are modified and read on the same thread. Note that |max_abs| will be
// zero in most calls and then have no effect of the stats. It is only updated
// approximately two times per second and can then change the stats.
task_queue_.PostTask([this, max_abs, samples_per_channel] {
UpdateRecStats(max_abs, samples_per_channel);
});
// Update recording stats which is used as base for periodic logging of the
// audio input state.
UpdateRecStats(max_abs, samples_per_channel);
return 0;
}
@ -397,13 +382,9 @@ int32_t AudioDeviceBuffer::RequestPlayoutData(size_t samples_per_channel) {
WebRtcSpl_MaxAbsValueW16(play_buffer_.data(), play_buffer_.size());
play_stat_count_ = 0;
}
// Update some stats but do it on the task queue to ensure that the members
// are modified and read on the same thread. Note that |max_abs| will be
// zero in most calls and then have no effect of the stats. It is only updated
// approximately two times per second and can then change the stats.
task_queue_.PostTask([this, max_abs, num_samples_out] {
UpdatePlayStats(max_abs, num_samples_out);
});
// Update playout stats which is used as base for periodic logging of the
// audio output state.
UpdatePlayStats(max_abs, num_samples_out);
return static_cast<int32_t>(num_samples_out);
}
@ -453,37 +434,37 @@ void AudioDeviceBuffer::LogStats(LogState state) {
int64_t time_since_last = rtc::TimeDiff(now_time, last_timer_task_time_);
last_timer_task_time_ = now_time;
Stats stats;
{
rtc::CritScope cs(&lock_);
stats = stats_;
stats_.max_rec_level = 0;
stats_.max_play_level = 0;
}
// Log the latest statistics but skip the first round just after state was
// set to LOG_START. Hence, first printed log will be after ~10 seconds.
if (++num_stat_reports_ > 1 && time_since_last > 0) {
uint32_t diff_samples = rec_samples_ - last_rec_samples_;
uint32_t diff_samples = stats.rec_samples - last_stats_.rec_samples;
float rate = diff_samples / (static_cast<float>(time_since_last) / 1000.0);
LOG(INFO) << "[REC : " << time_since_last << "msec, "
<< rec_sample_rate_ / 1000
<< "kHz] callbacks: " << rec_callbacks_ - last_rec_callbacks_
<< ", "
<< rec_sample_rate_ / 1000 << "kHz] callbacks: "
<< stats.rec_callbacks - last_stats_.rec_callbacks << ", "
<< "samples: " << diff_samples << ", "
<< "rate: " << static_cast<int>(rate + 0.5) << ", "
<< "level: " << max_rec_level_;
<< "level: " << stats.max_rec_level;
diff_samples = play_samples_ - last_play_samples_;
diff_samples = stats.play_samples - last_stats_.play_samples;
rate = diff_samples / (static_cast<float>(time_since_last) / 1000.0);
LOG(INFO) << "[PLAY: " << time_since_last << "msec, "
<< play_sample_rate_ / 1000
<< "kHz] callbacks: " << play_callbacks_ - last_play_callbacks_
<< ", "
<< play_sample_rate_ / 1000 << "kHz] callbacks: "
<< stats.play_callbacks - last_stats_.play_callbacks << ", "
<< "samples: " << diff_samples << ", "
<< "rate: " << static_cast<int>(rate + 0.5) << ", "
<< "level: " << max_play_level_;
<< "level: " << stats.max_play_level;
last_stats_ = stats;
}
last_rec_callbacks_ = rec_callbacks_;
last_play_callbacks_ = play_callbacks_;
last_rec_samples_ = rec_samples_;
last_play_samples_ = play_samples_;
max_rec_level_ = 0;
max_play_level_ = 0;
int64_t time_to_wait_ms = next_callback_time - rtc::TimeMillis();
RTC_DCHECK_GT(time_to_wait_ms, 0) << "Invalid timer interval";
@ -495,39 +476,37 @@ void AudioDeviceBuffer::LogStats(LogState state) {
void AudioDeviceBuffer::ResetRecStats() {
RTC_DCHECK_RUN_ON(&task_queue_);
rec_callbacks_ = 0;
last_rec_callbacks_ = 0;
rec_samples_ = 0;
last_rec_samples_ = 0;
max_rec_level_ = 0;
last_stats_.ResetRecStats();
rtc::CritScope cs(&lock_);
stats_.ResetRecStats();
}
void AudioDeviceBuffer::ResetPlayStats() {
RTC_DCHECK_RUN_ON(&task_queue_);
play_callbacks_ = 0;
last_play_callbacks_ = 0;
play_samples_ = 0;
last_play_samples_ = 0;
max_play_level_ = 0;
last_stats_.ResetPlayStats();
rtc::CritScope cs(&lock_);
stats_.ResetPlayStats();
}
void AudioDeviceBuffer::UpdateRecStats(int16_t max_abs,
size_t samples_per_channel) {
RTC_DCHECK_RUN_ON(&task_queue_);
++rec_callbacks_;
rec_samples_ += samples_per_channel;
if (max_abs > max_rec_level_) {
max_rec_level_ = max_abs;
RTC_DCHECK_RUN_ON(&recording_thread_checker_);
rtc::CritScope cs(&lock_);
++stats_.rec_callbacks;
stats_.rec_samples += samples_per_channel;
if (max_abs > stats_.max_rec_level) {
stats_.max_rec_level = max_abs;
}
}
void AudioDeviceBuffer::UpdatePlayStats(int16_t max_abs,
size_t samples_per_channel) {
RTC_DCHECK_RUN_ON(&task_queue_);
++play_callbacks_;
play_samples_ += samples_per_channel;
if (max_abs > max_play_level_) {
max_play_level_ = max_abs;
RTC_DCHECK_RUN_ON(&playout_thread_checker_);
rtc::CritScope cs(&lock_);
++stats_.play_callbacks;
stats_.play_samples += samples_per_channel;
if (max_abs > stats_.max_play_level) {
stats_.max_play_level = max_abs;
}
}

View File

@ -12,6 +12,7 @@
#define WEBRTC_MODULES_AUDIO_DEVICE_AUDIO_DEVICE_BUFFER_H_
#include "webrtc/base/buffer.h"
#include "webrtc/base/criticalsection.h"
#include "webrtc/base/task_queue.h"
#include "webrtc/base/thread_annotations.h"
#include "webrtc/base/thread_checker.h"
@ -36,6 +37,43 @@ class AudioDeviceBuffer {
LOG_ACTIVE,
};
struct Stats {
void ResetRecStats() {
rec_callbacks = 0;
rec_samples = 0;
max_rec_level = 0;
}
void ResetPlayStats() {
play_callbacks = 0;
play_samples = 0;
max_play_level = 0;
}
// Total number of recording callbacks where the source provides 10ms audio
// data each time.
uint64_t rec_callbacks = 0;
// Total number of playback callbacks where the sink asks for 10ms audio
// data each time.
uint64_t play_callbacks = 0;
// Total number of recorded audio samples.
uint64_t rec_samples = 0;
// Total number of played audio samples.
uint64_t play_samples = 0;
// Contains max level (max(abs(x))) of recorded audio packets over the last
// 10 seconds where a new measurement is done twice per second. The level
// is reset to zero at each call to LogStats().
int16_t max_rec_level = 0;
// Contains max level of recorded audio packets over the last 10 seconds
// where a new measurement is done twice per second.
int16_t max_play_level = 0;
};
AudioDeviceBuffer();
virtual ~AudioDeviceBuffer();
@ -92,9 +130,8 @@ class AudioDeviceBuffer {
// state = LOG_ACTIVE => logs are printed and the timer is kept alive.
void LogStats(LogState state);
// Updates counters in each play/record callback but does it on the task
// queue to ensure that they can be read by LogStats() without any locks since
// each task is serialized by the task queue.
// Updates counters in each play/record callback. These counters are later
// (periodically) read by LogStats() using a lock.
void UpdateRecStats(int16_t max_abs, size_t samples_per_channel);
void UpdatePlayStats(int16_t max_abs, size_t samples_per_channel);
@ -120,6 +157,8 @@ class AudioDeviceBuffer {
// Native (platform specific) audio thread driving the recording side.
rtc::ThreadChecker recording_thread_checker_;
rtc::CriticalSection lock_;
// Task queue used to invoke LogStats() periodically. Tasks are executed on a
// worker thread but it does not necessarily have to be the same thread for
// each task.
@ -184,41 +223,6 @@ class AudioDeviceBuffer {
// Counts number of times LogStats() has been called.
size_t num_stat_reports_ ACCESS_ON(task_queue_);
// Total number of recording callbacks where the source provides 10ms audio
// data each time.
uint64_t rec_callbacks_ ACCESS_ON(task_queue_);
// Total number of recording callbacks stored at the last timer task.
uint64_t last_rec_callbacks_ ACCESS_ON(task_queue_);
// Total number of playback callbacks where the sink asks for 10ms audio
// data each time.
uint64_t play_callbacks_ ACCESS_ON(task_queue_);
// Total number of playout callbacks stored at the last timer task.
uint64_t last_play_callbacks_ ACCESS_ON(task_queue_);
// Total number of recorded audio samples.
uint64_t rec_samples_ ACCESS_ON(task_queue_);
// Total number of recorded samples stored at the previous timer task.
uint64_t last_rec_samples_ ACCESS_ON(task_queue_);
// Total number of played audio samples.
uint64_t play_samples_ ACCESS_ON(task_queue_);
// Total number of played samples stored at the previous timer task.
uint64_t last_play_samples_ ACCESS_ON(task_queue_);
// Contains max level (max(abs(x))) of recorded audio packets over the last
// 10 seconds where a new measurement is done twice per second. The level
// is reset to zero at each call to LogStats().
int16_t max_rec_level_ ACCESS_ON(task_queue_);
// Contains max level of recorded audio packets over the last 10 seconds
// where a new measurement is done twice per second.
int16_t max_play_level_ ACCESS_ON(task_queue_);
// Time stamp of last timer task (drives logging).
int64_t last_timer_task_time_ ACCESS_ON(task_queue_);
@ -231,6 +235,13 @@ class AudioDeviceBuffer {
int64_t play_start_time_ ACCESS_ON(main_thread_checker_);
int64_t rec_start_time_ ACCESS_ON(main_thread_checker_);
// Contains counters for playout and recording statistics.
Stats stats_ GUARDED_BY(lock_);
// Stores current stats at each timer task. Used to calculate differences
// between two successive timer events.
Stats last_stats_ ACCESS_ON(task_queue_);
// Set to true at construction and modified to false as soon as one audio-
// level estimate larger than zero is detected.
bool only_silence_recorded_;