From 77ce9a55415a673422d424ed862be142d5e277ef Mon Sep 17 00:00:00 2001 From: henrika Date: Fri, 3 Feb 2017 02:19:17 -0800 Subject: [PATCH] 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} --- .../audio_device/audio_device_buffer.cc | 103 +++++++----------- .../audio_device/audio_device_buffer.h | 87 ++++++++------- 2 files changed, 90 insertions(+), 100 deletions(-) diff --git a/webrtc/modules/audio_device/audio_device_buffer.cc b/webrtc/modules/audio_device/audio_device_buffer.cc index e7a5da731a..8b49a3ffd0 100644 --- a/webrtc/modules/audio_device/audio_device_buffer.cc +++ b/webrtc/modules/audio_device/audio_device_buffer.cc @@ -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(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(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(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(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(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; } } diff --git a/webrtc/modules/audio_device/audio_device_buffer.h b/webrtc/modules/audio_device/audio_device_buffer.h index e2c6f2871a..1466e6934b 100644 --- a/webrtc/modules/audio_device/audio_device_buffer.h +++ b/webrtc/modules/audio_device/audio_device_buffer.h @@ -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_;